Profiling a rails app

Ruby JRuby
1

We have a strange resource contention issue of some type and I’m
trying to track it down. So I caught the blog post on the new built
in profiler and started playing around with it. This is jruby 1.6.4.

Using --profile I found that it’s only profiling the main thread, not
really where our application code gets run.

So using the profile api example from here
How to use the new JRuby profiler - Daniel Lucraft, I
put a profile block around the code in one of our controllers. But I
don’t see any profile information on the application code that’s in
the profile block, just a bunch of stuff about trinidad. What am I
doing wrong?

Chris

%total %self total self children calls
name

100% 0% 0.00 0.00 0.00
0 (top)
0.00 0.00 0.00
8/8 Trinidad::LogFormatter#format

                   0.00        0.00        0.00

8/8 (top)
100% 17% 0.00 0.00 0.00
8 Trinidad::LogFormatter#format
0.00 0.00 0.00
8/8 Java::JavaText::SimpleDateFormat#format
0.00 0.00 0.00
8/8 ConcreteJavaProxy.new
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::LogRecord#getMillis
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::LogRecord#getLevel
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::Level#getName
0.00 0.00 0.00
8/8 String#chomp
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::LogRecord#getMessage

                   0.00        0.00        0.00

8/8 Trinidad::LogFormatter#format
34% 34% 0.00 0.00 0.00
8 Java::JavaText::SimpleDateFormat#format

                   0.00        0.00        0.00

8/8 Trinidad::LogFormatter#format
16% 2% 0.00 0.00 0.00
8 ConcreteJavaProxy.new
0.00 0.00 0.00
8/8 Class#new

                   0.00        0.00        0.00

8/8 ConcreteJavaProxy.new
13% 2% 0.00 0.00 0.00
8 Class#new
0.00 0.00 0.00
8/8 ConcreteJavaProxy#initialize

                   0.00        0.00        0.00

8/8 Class#new
10% 2% 0.00 0.00 0.00
8 ConcreteJavaProxy#initialize
0.00 0.00 0.00
8/8 Java::JavaUtil::Date#__jcreate!

                   0.00        0.00        0.00

8/16 Java::JavaUtilLogging::LogRecord#getMillis
0.00 0.00 0.00
8/16 Trinidad::LogFormatter#format
9% 2% 0.00 0.00 0.00
16 Java::JavaUtilLogging::LogRecord#getMillis
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::LogRecord#getMillis

                   0.00        0.00        0.00

8/8 ConcreteJavaProxy#initialize
8% 8% 0.00 0.00 0.00
8 Java::JavaUtil::Date#__jcreate!

                   0.00        0.00        0.00

8/16 Java::JavaUtilLogging::LogRecord#getLevel
0.00 0.00 0.00
8/16 Trinidad::LogFormatter#format
7% 1% 0.00 0.00 0.00
16 Java::JavaUtilLogging::LogRecord#getLevel
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::LogRecord#getLevel

                   0.00        0.00        0.00

8/16 Java::JavaUtilLogging::Level#getName
0.00 0.00 0.00
8/16 Trinidad::LogFormatter#format
5% 1% 0.00 0.00 0.00
16 Java::JavaUtilLogging::Level#getName
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::Level#getName

                   0.00        0.00        0.00

8/8 Trinidad::LogFormatter#format
5% 5% 0.00 0.00 0.00
8 String#chomp

                   0.00        0.00        0.00

8/16 Java::JavaUtilLogging::LogRecord#getMessage
0.00 0.00 0.00
8/16 Trinidad::LogFormatter#format
5% 1% 0.00 0.00 0.00
16 Java::JavaUtilLogging::LogRecord#getMessage
0.00 0.00 0.00
8/16 Java::JavaUtilLogging::LogRecord#getMessage

2

Ok so it looks like it’s still just profiling the main thread. I see
a ticket on this in jira (http://jira.codehaus.org/browse/JRUBY-5862),
but no resolution.

So what’s the next best option for profiling all threads? Do I need
to go to java land?

Chris