How to Debug Ruby Performance Problems in Production

You know that performance is a feature. And a lot of performance problems can be found and fixed during development.

But what about those slowdowns that only show up in production? Do you have to add log messages to every single line of code? That would just slow things down even more! Or do you ship tons of tiny “maybe this fixes it” commits to see what sticks?

You don’t have to ruin your code to analyze it. Instead, try rbtrace-ing it.

Trace your running Ruby app

With rbtrace, you can detect performance problems, run code inside another Ruby process, and log method calls without having to add any code. Just add gem "rbtrace" to your Gemfile.

I learned about rbtrace from Sam Saffron’s amazing post about debugging memory leaks in Ruby (which you should really check out, if you haven’t already).

In that post, Sam used rbtrace to see all of the objects a process used:

bundle exec rbtrace -p $SIDEKIQ_PID -e 'Thread.new{GC.start;require "objspace";io=File.open("/tmp/ruby-heap.dump", "w"); ObjectSpace.dump_all(output: io); io.close}'

This is awesome. But there’s a whole lot more you can do.

What can you do with rbtrace?

Ever wanted to see the SQL statements you’re running in production (and how long they took)?

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID --methods "ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute_and_clear(sql)"             
*** attached to process 7897
ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#execute_and_clear(sql="SELECT  \"articles\".* FROM \"articles\" WHERE \"articles\".\"id\" = $1 LIMIT 1") <0.002631>

All method calls that take longer than 2 seconds?

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID --slow 2000
*** attached to process 8154
    Integer#times <2.463761>
        ArticlesController#create <2.558673>

Do you want to know every time a certain method gets called?

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID --methods "ActiveRecord::Persistence#save" 
*** attached to process 8154
ActiveRecord::Persistence#save <0.010964>

See which threads your app is running?

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID -e "Thread.list"
*** attached to process 8154
>> Thread.list
=> [#<Thread:0x007ff4fcc9a8a8@/usr/local/lib/ruby/gems/2.2.0/gems/puma-2.6.0/lib/puma/server.rb:269 sleep>, #<Thread:0x007ff4fcc9aa10@/usr/local/lib/ruby/gems/2.2.0/gems/puma-2.6.0/lib/puma/thread_pool.rb:148 sleep>, #<Thread:0x007ff4fcc9ab50@/usr/local/lib/ruby/gems/2.2.0/gems/puma-2.6.0/lib/puma/reactor.rb:104 sleep>, #<Thread:0x007ff4f98c0410 sleep>]

Yep, with -e you can run Ruby code inside your server:

~/Source/testapps/rbtrace jweiss$ rbtrace -p $RAILS_PID -e "ActiveRecord::Base.connection_config"
*** attached to process 8154
>> ActiveRecord::Base.connection_config
=> {:adapter=>"postgresql", :pool=>5, :timeout=>5000, :database=>"rbtrace_test"}

Yeah, OK, now I’m a little scared. But that’s still very cool. (And only users with permission to mess with the process can rbtrace it, so it’s probably OK).

rbtrace gives you a ton of tools to inspect your Ruby processes in staging and production. You can see how your processes are using (or abusing) memory, trace slow function calls, and even execute Ruby code.

You don’t have to create tons of test commits and log messages to fix problems. You can just hop on to the server, get some data, and hop back out. And even if I’m not totally comfortable using it in production yet, I’m sure it’ll even help out in our test environments.

How about you? What could you use rbtrace for?