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.

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
    }
  }
]

Get the Honeybadger newsletter

Each month we share news, best practices, and stories from the DevOps & monitoring community—exclusively for developers like you.
    author photo
    Starr Horne

    Starr Horne is a Rubyist and former Chief JavaScripter at Honeybadger. When she's not fixing bugs, she enjoys making furniture with traditional hand-tools, reading history and brewing beer in her garage in Seattle.

    More articles by Starr Horne
    An advertisement for Honeybadger that reads 'Move fast and fix things.'

    "We love Honeybadger. Not only is it a fab tool and very affordable, they feel like a partner - whenever we needed help we got FIRST CLASS service."

    Fix errors, eliminate performance bottlenecks, and dig into the details faster than ever before. With support for Ruby, Elixir, and 8 other languages, Honeybadger is the best way to gain real-time insights into your application’s health and performance.

    Get started for free
    Simple 5-minute setup — No credit card required
    Honeybadger's logo: a lightening bolt inside of a diamond shape.
    Product
    Stacks
    Company
    Resources
    Switching to Honeybadger