Jruby runs faster with "-r profile" then without

Hello - My development team is trying to track down a performance
problem
within our ruby code and we are using jruby 1.1.2. In an attempt to
determine the bottleneck we are running jruby with the -r profile option
to
gather the execution profile. When we do this the application runs up
to
10x faster. Has anyone seen this issue before?

View this message in context:
http://www.nabble.com/jruby-runs-faster-with-"-r-profile"-then-without-tp17699349p17699349.html
Sent from the JRuby - User mailing list archive at Nabble.com.


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

cwolfinger wrote:

Hello - My development team is trying to track down a performance problem
within our ruby code and we are using jruby 1.1.2. In an attempt to
determine the bottleneck we are running jruby with the -r profile option to
gather the execution profile. When we do this the application runs up to
10x faster. Has anyone seen this issue before?

That’s gotta be the most bizarre perf issue I’ve heard of :slight_smile:

My guess would be that turning on profiling turns off the compiler, and
that perhaps there’s something broken in the compiler that’s slowing
things down. Can you try to narrow it down at all?

  • Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

On Fri, Jun 6, 2008 at 3:10 PM, Charles Oliver N.
[email protected] wrote:

My guess would be that turning on profiling turns off the compiler, and that
perhaps there’s something broken in the compiler that’s slowing things down.
Can you try to narrow it down at all?

Or opposite could be true…interpreter is broken in some way and it
appears to be running 10x faster because it is not actually running…

-Tom


Blog: http://www.bloglines.com/blog/ThomasEEnebo
Email: [email protected] , [email protected]


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

The first alpha release of dramatis hit the streets today.

dramatis is a library available in Ruby and Python used to write
concurrent
programs based on the actor model of concurrency.

The dramatis web site is http://dramatis.mischance.net

The release is available as a gem on rubyforge at
http://rubyforge.org/projects/dramatis, supports both Ruby and Python,
and
comes with API docs, several examples, and a tutorial.

dramatis is pure ruby and runs on jruby. Of particular relevancy to
jruby is
that dramatis actor programs should be truly concurrent with jruby.
Unfortunately, I wasn’t able to verify this with earlier versions of
jruby
and I haven’t been able to test it with 1.1.2 release or trunk, but will
soon, if someone doesn’t beat me to it …


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Hello Charlie - Is it possible to turn off the JIT compiler for
everything
scoped by a given module?

  • Chase

Charles Oliver N.-2 wrote:


View this message in context:
http://www.nabble.com/jruby-runs-faster-with-"-r-profile"-then-without-tp17699349p17734652.html
Sent from the JRuby - User mailing list archive at Nabble.com.


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

On Mon, Jun 9, 2008 at 9:58 AM, cwolfinger [email protected]
wrote:

Hello Charlie - Is it possible to turn off the JIT compiler for everything
scoped by a given module?

  • Chase

Not currently. You could try and hack DefaultMethod.java to not do
JIT checks when desired module is seen, but I recommend narrowing it
down via JIT logging first.

If you turn on verbose flags to JIT you should be able to see which
method is recompiling that may be enough info for us to realize what
is going on. Add -J-Djruby.jit.logging=true and
-J-Djruby.jit.logging.verbose=true. You should see same method
printing over and over if it is getting recompiled.

-Tom


Blog: http://www.bloglines.com/blog/ThomasEEnebo
Email: [email protected] , [email protected]


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

That seems to be the problem. I turned off the JIT compiler and the
application was much faster then it was before. The slowdown in our
code
started when we were started calling Java classes from the ruby code
(basically using the JAXP parser as a replacement for using REXML for
some
particular intensive XML processing). What is really strange is that
the
same sections of code were invoke and appears that the JIT compiler was
being invoked each time the code was invoked. So the -r profile did not
make the execution faster - it looks like it just turned off the JIT
compiler.

I think we will develop a simple test case to illustrate what we are
seeing
and see if we can track it down.

Charles Oliver N.-2 wrote:


View this message in context:
http://www.nabble.com/jruby-runs-faster-with-"-r-profile"-then-without-tp17699349p17709694.html
Sent from the JRuby - User mailing list archive at Nabble.com.


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

So we profiled the code and the following code and the
builtin.javasupport.proxy.interface.append_features appears to be the
bottleneck once it is compiled by the JIT. Here are the top three we
found
using netbeans (~70% of the total time). Not sure what we could be
doing
that causes this performance issue.

uby.jit.ruby.C_3a_.jrubyInstalls.jruby_minus_1_dot_1_dot_1.lib.ruby.site_ruby.$1_dot_8.builtin.javasupport.proxy.interface.append_features10820297_28713819.block_0$RUBY$block(org.jruby.runtime.ThreadContext,
org.jruby.runtime.builtin.IRubyObject,
org.jruby.runtime.builtin.IRubyObject[]) 40.430847 61870 ms (40.4%)
751

ruby.jit.ruby.C_3a_.jrubyInstalls.jruby_minus_1_dot_1_dot_1.lib.ruby.site_ruby.$1_dot_8.builtin.javasupport.proxy.interface.append_features10820297_28713819.sclass_10$RUBY$singleton(org.jruby.runtime.ThreadContext,
org.jruby.runtime.builtin.IRubyObject,
org.jruby.runtime.builtin.IRubyObject[], org.jruby.runtime.Block)
16.164598
24736 ms (16.2%) 750

ruby.jit.ruby.C_3a_.jrubyInstalls.jruby_minus_1_dot_1_dot_1.lib.ruby.site_ruby.$1_dot_8.builtin.javasupport.proxy.interface.append_features10820297_28713819.sclass_1$RUBY$singleton(org.jruby.runtime.ThreadContext,
org.jruby.runtime.builtin.IRubyObject,
org.jruby.runtime.builtin.IRubyObject[], org.jruby.runtime.Block)
15.941524
24395 ms (15.9%) 751

Thomas E Enebo wrote:

JIT checks when desired module is seen, but I recommend narrowing it


View this message in context:
http://www.nabble.com/jruby-runs-faster-with-"-r-profile"-then-without-tp17699349p17739755.html
Sent from the JRuby - User mailing list archive at Nabble.com.


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Awesome discovery. Can you file this as a bug? There’s gotta be
somethign in there that the compiler is doing especially inefficiently.

If you can find any other similar problems, let us know. We’ve found
some in the past too.

cwolfinger wrote:

Thomas E Enebo wrote:

If you turn on verbose flags to JIT you should be able to see which


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

Yes - we just did that - we found that it is not recompiling the same
method
over and over again. From what we can tell as soon as the method is
compiled the slowdown occurs. Since the method is invoking a Java class
directly, I think the problem could be in that area. I am going to try
and
profile with netbeans to see if it can point out the bottleneck.

Thomas E Enebo wrote:

JIT checks when desired module is seen, but I recommend narrowing it


View this message in context:
http://www.nabble.com/jruby-runs-faster-with-"-r-profile"-then-without-tp17699349p17735485.html
Sent from the JRuby - User mailing list archive at Nabble.com.


To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email