Jruby and Thread Dumps

OK, today I would like to share a little patch I was toying around with in the JRuby world.

First a little background. We run some Ruby on Rails application via JRuby in JavaEE web containers, either in Tomcat or in GlassFish. That’s all nice and good when everything is working. But we have some requests once in a while which take forever. So far nobody could find a good cause for that and it usually happens ones the server is up and running for a while:-( The JVM has a helper for situations like that: you can send a SIGQUIT to the running process and it will produce a nice thread dump for all threads. That works OK for Java since it gives you the source files and line numbers, so you can get a good idea where & what your different threads are doing. Trying to do that for JRuby, you get a nice dump of the JRuby internals, but no real useful information at the Ruby level:-(

A SIGQUIT thread dump for a mongrel setup (my dev environment) looks something like the piece below, for a Tomcat/GF setup, it would have many more threads but they would be very similar, at least the tops of them.  Look at it and try to spot, that the sleep() on the top is a sleep() I added at the first line of one of our RoR views.

~/testapp$ ~/jruby/bin/jruby -S script/server  &
[1] 8260
mw install MwSignalHandler(USR2)
=> Booting Mongrel
=> Rails 2.3.11 application starting on http://0.0.0.0:3000
** [NewRelic] NewRelic Agent Developer Mode enabled.
** [NewRelic] To view performance information, go to http://localhost:3000/newrelic
** [NewRelic] New Relic RPM Agent 2.9.5 Initialized: pid = 8260
** [NewRelic] Agent Log found in ~/testapp/log/newrelic_agent.log
=> Call with -d to detach
=> Ctrl-C to shutdown server

~/testapp$ jobs
[1]+  Running                 ~/jruby/bin/jruby -S script/server &
~/testapp$ kill -QUIT %1
2012-08-07 20:37:00
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.1-b02 mixed mode):

"RubyThread-32: ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:285" daemon prio=10 tid=0x00007f55ac099800 nid=0x20a5 in Object.wait() [0x00007f55aa7bc000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000fe1b29f8> (a org.jruby.RubyThread)
at org.jruby.RubyThread.sleep(RubyThread.java:801)
- locked <0x00000000fe1b29f8> (a org.jruby.RubyThread)
- locked <0x00000000fe1b29f8> (a org.jruby.RubyThread)
at org.jruby.RubyKernel.sleep(RubyKernel.java:824)
at org.jruby.RubyKernel$s$0$1$sleep.call(RubyKernel$s$0$1$sleep.gen:65535)
at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:630)
at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:207)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:312)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:169)
at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:75)
at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:212)
at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:187)
at org.jruby.RubyClass.finvoke(RubyClass.java:576)
at org.jruby.RubyBasicObject.send(RubyBasicObject.java:2772)
at org.jruby.RubyKernel.send(RubyKernel.java:2097)
at org.jruby.RubyKernel$s$send.call(RubyKernel$s$send.gen:65535)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:342)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:212)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:221)
at org.jruby.ast.CallTwoArgBlockNode.interpret(CallTwoArgBlockNode.java:62)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
at org.jruby.runtime.InterpretedBlock.evalBlockBody(InterpretedBlock.java:374)
at org.jruby.runtime.InterpretedBlock.yield(InterpretedBlock.java:295)
at org.jruby.runtime.InterpretedBlock.yieldSpecific(InterpretedBlock.java:229)
at org.jruby.runtime.Block.yieldSpecific(Block.java:99)
at org.jruby.ast.ZYieldNode.interpret(ZYieldNode.java:25)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:75)
at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:212)
at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:187)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:322)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:178)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:187)
at org.jruby.ast.CallOneArgBlockNode.interpret(CallOneArgBlockNode.java:60)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:75)
at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:255)
at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:203)
at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:91)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:342)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:212)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:216)
at org.jruby.ast.FCallSpecialArgBlockPassNode.interpret(FCallSpecialArgBlockPassNode.java:40)
at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
at org.jruby.runtime.InterpretedBlock.evalBlockBody(InterpretedBlock.java:374)
at org.jruby.runtime.InterpretedBlock.yield(InterpretedBlock.java:295)
at org.jruby.runtime.InterpretedBlock.yieldSpecific(InterpretedBlock.java:229)
at org.jruby.runtime.Block.yieldSpecific(Block.java:99)
at rubyjit.trace_method_execution_with_scope_78ABF05203AC3E33573FAF5CB6B4659DC346B6C3.chained_2_ensure_1$RUBY$__ensure__(~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:62)
at rubyjit.trace_method_execution_with_scope_78ABF05203AC3E33573FAF5CB6B4659DC346B6C3.__file__(~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:61)
at rubyjit.trace_method_execution_with_scope_78ABF05203AC3E33573FAF5CB6B4659DC346B6C3.__file__(~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:87)
at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:272)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:80)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:89)
at org.jruby.ast.CallManyArgsBlockNode.interpret(CallManyArgsBlockNode.java:59)
....

As you can see, it’s mostly AST handling in the JRuby runtime but not much useful. I actually took only the top of the dump, it’s about 1000 lines long, but I wanted to show that it sometimes has some references to JITed methods which can give you a hint about a location. But even that’s not really granular:-(

But JRuby can create nice Ruby level stack traces when it hits a `Ruby level exception’. So the runtime system has to keep all that information somewhere. After that realisation, I started looking at the OpenJDK and the JRuby sources.

I looked at OpenJDK to see if there is any possibility to combine the Java and JRuby dumps somehow. Either as an additional section or somehow intermixed. But I could not find any way to do that, the SIGQUIT handling is completely done at the C/C++ level without an easy way to extend it:-( Even chaining signal handlers for the SIGQUIT does not seem to be possible, at least not in the OpenJDK and the Oracle JDK. So I had to use a different way, I decided to use SIGUSR2 for now, but that could easily be switched in the patch.

The excursion into JRuby was to find where it kept it’s stack information and see if there is a way to print it whenever I wanted to. Most of it is handled in ThreadContext.java and I found a reasonably usable spot for my hack in RubyThread.java. So when I now send a SIGUSR2 to my patched jruby, I get a Ruby level tread dump for all Ruby threads.

For the same sleep(), that looks something like

~/testapp$ kill -USR2 %1
========== MwSignalHandler.signalAction(USR2) ==========
========== RubyThread = Thread[main,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@4b0fc9d1
#<Class:0xea211cf>#run at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/handler/mongrel.rb:37
#<Class:0x10cbd8dc>#(root) at ~/testapp/vendor/bundle/jruby/1.8/gems/rails-2.3.11/lib/commands/server.rb:110
========== RubyThread = Thread[RubyThread-1: ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/stats_engine.rb:29,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@798aded6
NewRelic::Agent::StatsEngine#spawn_sampler_thread at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/stats_engine.rb:31
========== RubyThread = Thread[Thread-2,5,]
========== RubyThread = Thread[Thread-3,5,]
========== RubyThread = Thread[RubyThread-12: ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:268,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@c2bf1f1
Mongrel::HttpServer#run at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:271
========== RubyThread = Thread[RubyThread-13: ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:285,5,main]
========== ThreadContext= org.jruby.runtime.ThreadContext@19190b75
ActionView::Base::CompiledTemplates#_run_erb_app47views47home47index46html46erb at ~/testapp/app/views/home/index.html.erb:0
#<Class:0x136157d8>#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/renderable.rb:33
ActionView::Base#with_template at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:305
ActionView::Renderable#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/renderable.rb:29
#<Class:0x136157d8>#render_with_trace_View___path__Rendering at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:160
ActionView::Template#render_with_trace_View___path__Rendering at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:159
ActionView::Template#render_template at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/template.rb:204
ActionView::Base#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:264
ActionView::Base#_render_with_layout at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:347
ActionView::Base#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_view/base.rb:261
ActionController::Base#render_for_file at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:1251
ActionController::Base#render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:935
HomeController#render_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:50
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
Benchmark#realtime at ~/jruby/lib/ruby/1.8/benchmark.rb:307
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
ActionController::Benchmarking#render_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:50
ApplicationController#render at ~/testapp/app/controllers/application_controller.rb:117
ActionController::Base#default_render at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:1327
ActionController::Base#perform_action at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:1333
ActionController::Filters::InstanceMethods#call_filters at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/filters.rb:616
ActionController::Filters::InstanceMethods#perform_action_with_filters at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/filters.rb:609
HomeController#perform_action_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:67
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
Benchmark#realtime at ~/jruby/lib/ruby/1.8/benchmark.rb:307
#<Class:0x669b9a30>#ms at ~/testapp/vendor/bundle/jruby/1.8/gems/activesupport-2.3.11/lib/active_support/core_ext/benchmark.rb:16
ActionController::Benchmarking#perform_action_with_benchmark at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/benchmarking.rb:67
ActionController::Rescue#perform_action_with_rescue at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/rescue.rb:159
ActionController::Flash::InstanceMethods#perform_action_with_flash at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/flash.rb:150
HomeController#perform_action_with_newrelic_trace at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:137
NewRelic::Agent::MethodTracer#trace_method_execution_with_scope at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:61
HomeController#perform_action_with_newrelic_trace at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:121
NewRelic::Agent::MethodTracer#trace_method_execution_no_scope at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/method_tracer.rb:37
NewRelic::Agent::Instrumentation::ControllerInstrumentation#perform_action_with_newrelic_trace at ~/testapp/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:116
ActionController::Base#process at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:531
ActionController::Filters::InstanceMethods#process_with_filters at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/filters.rb:605
#<Class:0xdf20541>#process at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:390
#<Class:0xdf20541>#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/base.rb:385
ActionController::Routing::RouteSet#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/routing/route_set.rb:437
ActionController::Dispatcher#dispatch at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:86
ActionController::Dispatcher#_call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:120
ActionController::Dispatcher#build_middleware_stack at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:129
ActionController::StringCoercion#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/string_coercion.rb:24
Rack::Head#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/head.rb:8
Rack::MethodOverride#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/methodoverride.rb:23
ActionController::ParamsParser#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/params_parser.rb:14
ActionController::Session::AbstractStore#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/session/abstract_store.rb:176
ActiveRecord::QueryCache#call at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/query_cache.rb:28
ActiveRecord::ConnectionAdapters::QueryCache#cache at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/connection_adapters/abstract/query_cache.rb:33
ActiveRecord::QueryCache::ClassMethods#cache at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/query_cache.rb:8
ActiveRecord::QueryCache#call at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/query_cache.rb:27
ActiveRecord::ConnectionAdapters::ConnectionManagement#call at ~/testapp/vendor/bundle/jruby/1.8/gems/activerecord-2.3.11/lib/active_record/connection_adapters/abstract/connection_pool.rb:360
ActionController::Failsafe#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/failsafe.rb:25
Rack::Lock#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/lock.rb:10
Rack::Lock#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/lock.rb:10
ActionController::Dispatcher#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:113
#<Class:0x56683a8d>#run at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/reloader.rb:33
ActionController::Dispatcher#call at ~/testapp/vendor/bundle/jruby/1.8/gems/actionpack-2.3.11/lib/action_controller/dispatcher.rb:107
Rails::Rack::Static#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rails-2.3.11/lib/rails/rack/static.rb:30
Rack::URLMap#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/urlmap.rb:48
Rack::URLMap#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/urlmap.rb:40
Rails::Rack::LogTailer#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rails-2.3.11/lib/rails/rack/log_tailer.rb:16
Rack::ContentLength#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/content_length.rb:12
Rack::Chunked#call at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/chunked.rb:14
Rack::Handler::Mongrel#process at ~/testapp/vendor/bundle/jruby/1.8/gems/rack-1.1.2/lib/rack/handler/mongrel.rb:66
Mongrel::HttpServer#process_client at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:158
Mongrel::HttpServer#process_client at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:157
Mongrel::HttpServer#run at ~/testapp/vendor/bundle/jruby/1.8/gems/mongrel-1.1.5-java/lib/mongrel.rb:284

The line numbers seem to be 0 based but that’s how JRuby stores the info internally. I did not really change that. I did some checks that it seems to work as expected.

I did not do the complete github fork & patch routine yet, if I find the need to change this more in the future, I probably will do that. But for now, jruby-1.6.7.2-SigUSR2Patch.tar is my little patch. It contains the changed source and all the class files for org.jruby.RubyThread.java based on JRuby 1.6.7.2. That source file did not change since 1.6.5, so I don’t expect many changes in the next couple of iterations. Applying the changes (for tests) is pretty easy, just stick all the *.class files into the jruby.jar to replace the originals.

But as always, this is a hack, use at your own risk!! But have fun trying it out;-)