An Instrumented Library in ~30 Lines

The Full ~30 Lines

For the first time ever, I am going to lead with the end of the story. Here is the full ~30 lines that I will break down in detail during the rest of this post.

require 'forwardable'

module Foo
  module Instrumenters
    class Noop
      def self.instrument(name, payload = {})
        yield payload if block_given?
      end
    end
  end

  class Client
    extend Forwardable

    def_delegator :@instrumenter, :instrument

    def initialize(options = {})
      # some other setup for the client ...
      @instrumenter = options[:instrumenter] || Instrumenters::Noop
    end

    def execute(args = {})
      instrument('client_execute.foo', args: args) { |payload|
        result = # do some work...
        payload[:result] = result
        result
      }
    end
  end
end

client = Foo::Client.new({
  instrumenter: ActiveSupport::Notifications,
})

client.execute(...) # I AM INSTRUMENTED!!!

The Dark Side

A while back, statsd grabbed a hold of the universe. It swept in like an elf on a unicorn and we all started keeping track of stuff that previously was a pain to keep track of.

Like any wave of awesomeness, it came with a dark side that was felt, but mostly overlooked. Dark side? Statsd? Graphite? You must be crazy! Nope, not me, definitely not crazy this one. Not. At. All.

What did we all start doing in order to inject our measuring? Yep, we started opening up classes in horrible ways and creating hooks into libraries that sometimes change rapidly. Many times, updating a library would cause a break in the stats reporting and require effort to update the hooks.

The Ideal

Now that the wild west is settling a bit, I think some have started to reflect on that wave of awesomeness and realized something.

I no longer want to inject my own instrumentation into your library. Instead, I want to tell your library where it should send the instrumentation.

The great thing is that ActiveSupport::Notifications is pretty spiffy in this regard. By simply allowing your library to talk to an “instrumenter” that responds to instrument with an event name, optional payload, and optional block, you can make all your library’s users really happy.

The great part is:

1. You do not have to force your users to use active support. They simply need some kind of instrumenter that responds in similar fashion.
2. They no longer have to monkey patch to get metrics.
3. You can point them in the right direction as to what is valuable to instrument in your library, since really you know it best.

There are a few good examples of libraries (faraday, excon, etc.) doing this, but I haven’t seen a great post yet, so here is my attempt to point you in what I feel is the right direction.

The Interface

First, like I said above, we do not want to force requiring active support. Rather than require a library, it is always better to require an interface.

The interface that we will require is the one used by active support, but an adapter interface could be created for any instrumenter that we want to support. Here is what it looks like:

instrumenter.instrument(name, payload) { |payload|
  # do some code here that should be instrumented
  # we expect payload to be yielded so that additional 
  # payload entries can be included during the 
  # computation inside the block
}

Second, we have two options.

1. Either have an instrumenter or not. If so, then call instrument on the instrumenter. If not, then do not call instrument.
2. The option, which I prefer, is to have a default instrumenter that does nothing. Aptly, I call this the noop instrumenter.

The Implementation

Let’s pretend our library is named foo, therefore it will be namespaced with the module Foo. I typically namespace the instrumenters in a module as well. Knowing this, our noop instrumenter would look like this:

module Foo
  module Instrumenters
    class Noop
      def self.instrument(name, payload = {})
        yield payload if block_given?
      end
    end
  end
end

As you can see, all this instrumenter does is yield the payload if a block is given. As I mentioned before, we yield payload so that the computation inside the block can add entries to the payload, such as the result.

Now that we have a default instrumenter, how can we use it? Well, let’s imagine that we have a Client class in foo that is the main entry point for the gem.

module Foo
  class Client
    def initialize(options = {})
      # some other setup for the client ...
      @instrumenter = options[:instrumenter] || Instrumenters::Noop
    end
  end
end

This code simply allows people to pass in the instrumenter that they would like to use through the initialization options. Also, by default if no instrumenter is provided, we use are noop version that just yields the block and moves on.

Note: the use of || instead of #fetch is intentional. It prevents a nil instrumenter from being passed in. There are other ways around this, but I have found using the noop instrumenter in place of nil, better than complaining about nil.

Now that we have an :instrumenter option, someone can quite easily pass in the instrumenter that they would like to use.

client = Foo::Client.new({
  :instrumenter => ActiveSupport::Notifications,
})

Boom! Just like that we’ve allowed people to inject active support notifications, or whatever instrumenter they want into our library. Anyone else getting excited?

Once we have that, we can start instrumenting the valuable parts. Typically what I do is I setup delegation of the instrument to the instrumenter using ruby’s forwardable library:

require 'forwardable'

module Foo
  class Client
    extend Forwardable

    # forward instrument in this class to @instrumenter, for those unfamilier
    # with forwardable.
    def_delegator :@instrumenter, :instrument

    def initialize(options = {})
      # some other setup for the client ...
      @instrumenter = options[:instrumenter] || Instrumenters::Noop
    end
  end
end

Now we can use the instrument method directly anywhere in our client instance. For example, let’s say that client has a method named execute that we would like to instrument.

module Foo
  class Client
    def execute(args = {})
      instrument('client_execute.foo', args: args) { |payload|
        result = # do some work...
        payload[:result] = result
        result
      }
    end
  end
end

With just a tiny wrap of the instrument method, the users of our library can do a ridiculous amount of instrumentation. For one, note that we pass the args and the result along with the payload. This means our users can create a log subscriber and log each method call with timing, argument, and result information. Incredibly valuable!

They can also create a metrics subscriber that sends the timing information to instrumental, metriks, statsd, or whatever.

The Bonus

You can even provide log subscribers and metric subscribers in your library, which means instrumentation for your users is simply a require away. For example, here is the log subscriber I added to cassanity.

require 'securerandom'
require 'active_support/notifications'
require 'active_support/log_subscriber'

module Cassanity
  module Instrumentation
    class LogSubscriber < ::ActiveSupport::LogSubscriber
      def cql(event)
        return unless logger.debug?

        name = '%s (%.1fms)' % ["CQL Query", event.duration]

        # execute arguments are always an array where the first element is the
        # cql string and the rest are the bound variables.
        cql, *args = event.payload[:execute_arguments]
        arguments = args.map { |arg| arg.inspect }.join(', ')

        query = "#{cql}"
        query += " (#{arguments})" unless arguments.empty?

        debug "  #{color(name, CYAN, true)}  [ #{query} ]"
      end
    end
  end
end

Cassanity::Instrumentation::LogSubscriber.attach_to :cassanity

All the users of cassanity need to do to get logging of the CQL queries they are performing and their timing is require a file (and have activesupport in their gemfile):

require 'cassanity/instrumentation/log_subscriber'

And they get logging goodness like this in their terminal:

The Accuracy

But! BUT, you say. What about the tests? Well, my friend, I have that all wrapped up for you as well. Since it is so easy to pass through an instrumenter to our library, we should probably also have an in memory instrumenter that keeps track of the events instrumented, so you can test thoroughly, and ensure you don’t hose your users with incorrect instrumentation.

The previous sentence was quite a mouthful, so my next one will be short and sweet. For testing, I created an in-memory instrumenter that simply stores each instrumented event with name, payload, and the computed block result for later comparison. Check it:

module Foo
  module Instrumenters
    class Memory
      Event = Struct.new(:name, :payload, :result)

      attr_reader :events

      def initialize
        @events = []
      end

      def instrument(name, payload = {})
        result = if block_given?
          yield payload
        else
          nil
        end

        @events << Event.new(name, payload, result)

        result
      end
    end
  end
end

Now in your tests, you can do something like this when you want to check that your library is correctly instrumenting:

instrumenter = Foo::Instrumenters::Memory.new

client = Foo::Client.new({
  instrumenter: instrumenter,
})

client.execute(...)

payload = {... something .. }
event = instrumenter.events.last

assert_not_nil event
assert_equal 'client_execute.foo', event.name
assert_equal payload, event.payload

The End Result

With two instrumenters (noop, memory) and a belief in interfaces, we have created immense value.

Further Reading

Without any further ado, here are a few of the articles and decks that I read recently related to this.

• RailsCasts: Notifications in Rails 3
• Digging Deep with ActiveSupport Notifications
• Code Charcuterie
• Instrument Anything in Rails 3
• On Notifications, Log Subscribers and Bringing Sanity to Rails Logs

Fin

Go forth and instrument all the things!