Using GDB to inspect a running Ruby process

This job shouldn’t be taking this long!

That’s not a great thing to have to say, is it? However, I bet you’ve said it before and may not have immediately know why.

With liberal use of puts and maybe pry, you can figure out what a problem might be next time you run it, but sometimes you need to figure out what that problem is right now.

As it turns out, and I know this is a shocker, Ruby processes are just regular processes. They can be debugged with gdb.

Having recently had the need to find out why a job of mine was running particularly slowly, I found out about this lovely tool the hard way: frantic googling. I found some very useful functions for gdb in a blog post by Rasmus on Ruby callstacks.

define redirect_stdout
  call rb_eval_string("$_old_stdout, $stdout = $stdout, File.open('/tmp/ruby-debug.' + Process.pid.to_s, 'a'); $stdout.sync = true")
end

define ruby_eval
  call(rb_p(rb_eval_string_protect($arg0,(int*)0)))
end

How to use these:

1. Start up gdb by running gdb /path/to/ruby PID, where /path/to/ruby is the full path to the actual ruby binary and PID is the process ID of the ruby you want to check out.
2. Paste those functions above into the gdb prompt (you might also want to store them in ~/.gdbinit for later).
3. Run redirect_stdout, which will put all the ruby output into a file called /tmp/ruby-debug.PID where PID in this case if the process id of gdb — not terribly important, but a differentiator in case you do this a lot.
4. Run commands via ruby_eval('Kernel.caller') and object_id and things like that. You should be able to get local variables from wherever you broke into the program.

These ruby_eval commands will output into the tempfile that redirect_stdout created, so you’ll need to tail -f that file in a different console. Now, with that small headache over with, you can see exactly where your program is and if there is a stupid loop where you forgot to check a boundary condition, or what thing you’re doing with a regular expression on where you should have just used String#index.

Written by Jon Yurek.

How to Splunk with Heroku

Splunk is company that offers logging services. They went public last year, have a market cap of over $3 billion, and are headquartered in San Francisco’s SoMa neighborhood.

I’ve tried Loggly and Papertrail. In my opinion, Splunk is the best of the bunch due to its:

• Real-time or very-near-real-time data discovery.
• Wildcard search.
• Timespan dragging.

Loggly and Papertrail offer Heroku add-ons but Splunk doesn’t. So, setup is a bit more complex with Splunk. Here’s how to do it.

Go to Splunk Storm. Create an account.

Once signed in, create a project:

You can start with a free plan:

Click “Network data”:

Click “Authorize your IP address”:

Click “Automatically”:

You now have 15 minutes to send Splunk data. Copy the URL in the text box:

Then, add a Heroku syslog drain:

heroku drains:add logs4.splunkstorm.com:YOURSPLUNKPORT

Perform a few activities on your app to send data to the drain. Then, click “Explore data”:

Perform a search, maybe using wildcards:

I haven’t been diligent about saving common searches. If you have interesting saved Splunk searches you can share, please comment.

Filter by dragging a timespan:

Watch how quickly the data loads.

On Rails apps, the default production log level includes enough data to be useful in Splunk. Change it to DEBUG only when debugging:

heroku config:add LOG_LEVEL=DEBUG

At the DEBUG level, Rails will print SQL queries to the logs, which can be useful but may also contain sensitive data as config.filter_parameters does not apply to SQL queries.

Written by Dan Croak.

Tail your test logs

Rails’ logs contain valuable information. You’ve probably seen output like the following:

Processing PagesController#show (for 127.0.0.1 at 2009-09-09 19:07:29) [GET]
  Parameters: {"id"=>"about"}
Rendering template within layouts/narrow
Rendering pages/about
Rendered shared/_navigation (2.7ms)
Rendered shared/_flashes (0.8ms)
Rendered shared/_javascript (1.2ms)
Completed in 28ms (View: 21, DB: 0) | 200 OK [http://localhost/]

In my case, I ran script/server. If you’re running Passenger, you might run:

tail -f log/development.log

Tail your test log

If I do not understand a functional test failure, I run my tests in one shell and tail my test log in another. Usually, I’m checking to make sure the params are correct*.

tail -f log/test.log

Tail your Cucumber log

Cucumber is pretty cool. One downside is lack of information in the backtrace. You can find out more by tailing the log!

tail -f log/cucumber.log

There’s a lot going on, isn’t there?

Watching test logs, especially in the Test::Unit/Shoulda world, reminds me:

• how much of the stack gets executed in functional tests
• the quieting, focusing effect that stubbing and spying can have
• stubbing and spying aren’t enough when you have to worry about what is happening in the view during your functional tests