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 Chief JavaScripter at Honeybadger.io. When she's not neck-deep in other people's 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 'Turn your logs into events.'

    "Splunk-like querying without having to sell my kidneys? nice"

    That’s a direct quote from someone who just saw Honeybadger Insights. It’s a bit like Papertrail or DataDog—but with just the good parts and a reasonable price tag.

    Best of all, Insights logging is available on our free tier as part of a comprehensive monitoring suite including error tracking, uptime monitoring, status pages, and more.

    Start logging 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