Spying on running Ruby processes

Did you know that it's possible to log all method calls as they occur in a running process in real time? How about injecting code to be executed inside of a running process? You can – via the magic of the rbtrace gem.

Did you know that it's possible to log all method calls as they occur in a running process in real time? How about injecting code to be executed inside of a running process? You can – via the magic of the rbtrace gem.

The rbtrace gem comes with two parts. The first is a library that you include in the code that you want to trace. The second is a commandline utility for querying trace data.

Let's take a look at a simple example. The code that we're going to trace is really simple. All we have to do is require the rbtrace gem.

require 'rbtrace'
require 'digest'
require 'securerandom'

# An infinite loop
while true

  # Do some work. 
  Digest::SHA256.digest SecureRandom.random_bytes(2**8)

  # Sleep for one second on every iteration.
  sleep 1
end

Now let's run this program:

$ ruby trace.rb &
[1] 12345

We take this process ID and give it to the rbtrace command line tool. The -f option indicates "firehose" mode, which prints everything to screen.

$ rbtrace -p 12345 -f
*** attached to process 12345
Fixnum#** <0.000010>
SecureRandom.random_bytes
  Integer#to_int <0.000005>
  SecureRandom.gen_random
    OpenSSL::Random.random_bytes <0.002223>
  SecureRandom.gen_random <0.002243>
SecureRandom.random_bytes <0.002290>

Digest::SHA256.digest
  Digest::Class#initialize <0.000004>
  Digest::Instance#digest
    Digest::Base#reset <0.000005>
    Digest::Base#update <0.000210>
    Digest::Base#finish <0.000006>
    Digest::Base#reset <0.000005>
  Digest::Instance#digest <0.000267>
Digest::SHA256.digest <0.000308>

Kernel#rand
  Kernel#respond_to_missing? <0.000008>
Kernel#rand <0.000071>

Kernel#sleep <1.003233>

This is really cool! We can see every method that gets called along with the time spent in that method.

If we wanted to home in on a specific method, we could use the -m option.

$ rbtrace -p 12345 -m digest
*** attached to process 12345
Digest::SHA256.digest
  Digest::Instance#digest <0.000201>
Digest::SHA256.digest <0.000220>

Digest::SHA256.digest
  Digest::Instance#digest <0.000287>
Digest::SHA256.digest <0.000343>

Probably the coolest use of this gem is to get a heap dump from a running web server. Heap dumps contain every object in memory along with a bunch of metadata and are very useful for debugging memory leaks in production.

To get the heap dump use a command like the one below, taken from this post by Sam Saffron.

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

Be warned though, heap dumps can be very big – on the order of a few hundred megabytes for a rails process. Here's a very small sample:

[
  {
    "type": "ROOT",
    "root": "vm",
    "references": [
      "0x7fb7d38bc3f0",
      "0x7fb7d38b79b8",
      "0x7fb7d38dff80",
      "0x7fb7d38bff50",
      "0x7fb7d38bff00",
      "0x7fb7d38b4bf0",
      "0x7fb7d38bfe88",
      "0x7fb7d38bfe60",
      "0x7fb7d38ddc80",
      "0x7fb7d38dffa8",
      "0x7fb7d382fbd0",
      "0x7fb7d382fbf8"
    ]
  },
  {
    "type": "ROOT",
    "root": "machine_context",
    "references": [
      "0x7fb7d382fbf8",
      "0x7fb7d382fbf8",
      "0x7fb7d3827d40",
      "0x7fb7d3827a70",
      "0x7fb7d38becb8",
      "0x7fb7d38bed08",
      "0x7fb7d38ddc80",
      "0x7fb7d3827e58",
      "0x7fb7d3827e58",
      "0x7fb7d38becb8",
      "0x7fb7d38becb8",
      "0x7fb7d38bc328",
      "0x7fb7d38bc378",
      "0x7fb7d38ddc80",
      "0x7fb7d3835008",
      "0x7fb7d3835008",
      "0x7fb7d3835008",
      "0x7fb7d3835008",
      "0x7fb7d3835008"
    ]
  },
  {
    "type": "ROOT",
    "root": "global_list",
    "references": [
      "0x7fb7d38dff58"
    ]
  },
  {
    "type": "ROOT",
    "root": "global_tbl",
    "references": [
      "0x7fb7d38c6dc8",
      "0x7fb7d38c6dc8",
      "0x7fb7d38c65f8",
      "0x7fb7d38c6580",
      "0x7fb7d38c6508",
      "0x7fb7d38c6580",
      "0x7fb7d38c6288",
      "0x7fb7d38c6288",
      "0x7fb7d38c6288",
      "0x7fb7d38c6288",
      "0x7fb7d38c6288",
      "0x7fb7d38bc418",
      "0x7fb7d38bc418",
      "0x7fb7d38bc418",
      "0x7fb7d3835328",
      "0x7fb7d3835328"
    ]
  },
  {
    "address": "0x7fb7d300c5e8",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 10,
    "value": "@exit_code",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300c7a0",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 9,
    "value": "exit_code",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300c908",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 19,
    "value": "SystemExitException",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300cb60",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 17,
    "value": "VerificationError",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300cd90",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 19,
    "value": "RubyVersionMismatch",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300cfe8",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 21,
    "value": "RemoteSourceException",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300d1f0",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "fstring": true,
    "bytesize": 25,
    "value": "RemoteInstallationSkipped",
    "encoding": "US-ASCII",
    "memsize": 66,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300d3a8",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "fstring": true,
    "bytesize": 27,
    "value": "RemoteInstallationCancelled",
    "encoding": "US-ASCII",
    "memsize": 68,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300d560",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 11,
    "value": "RemoteError",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300d830",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "fstring": true,
    "bytesize": 26,
    "value": "OperationNotSupportedError",
    "encoding": "US-ASCII",
    "memsize": 67,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300dbc8",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 12,
    "value": "InstallError",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300e898",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 9,
    "value": "requester",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300eaa0",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 13,
    "value": "build_message",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300ec30",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 8,
    "value": "@request",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300ede8",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "embedded": true,
    "fstring": true,
    "bytesize": 7,
    "value": "request",
    "encoding": "US-ASCII",
    "memsize": 40,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  },
  {
    "address": "0x7fb7d300efa0",
    "type": "STRING",
    "class": "0x7fb7d38dcee8",
    "frozen": true,
    "fstring": true,
    "bytesize": 27,
    "value": "ImpossibleDependenciesError",
    "encoding": "US-ASCII",
    "memsize": 68,
    "flags": {
      "wb_protected": true,
      "old": true,
      "long_lived": true,
      "marked": true
    }
  }
]
author photo

Starr Horne

Starr Horne is a Rubyist and Chief Javascripter at Honeybadger.io. When he's not neck-deep in other people's bugs, he enjoys making furniture with traditional hand-tools, reading history and brewing beer in his garage in Seattle.

“We’ve looked at a lot of error management systems. Honeybadger is head and shoulders above the rest and somehow gets better with every new release.”
Michael Smith
Try Error Monitoring Free for 15 Days
Are you using Bugsnag, Rollbar, or Airbrake for your monitoring? Honeybadger includes exception, uptime, and check-in monitoring — all for probably less than you’re paying now. Discover why so many companies are switching to Honeybadger here.
Try Error Monitoring Free for 15 Days
Stop digging through chat logs to find the bug-fix someone mentioned last month. Honeybadger's built-in issue tracker keeps discussion central to each error, so that if it pops up again you'll be able to pick up right where you left off.
Try Error Monitoring Free for 15 Days
"Wow — Customers are blown away that I email them so quickly after an error."
Chris Patton
Try Error Monitoring Free for 15 Days