bitmonkey

Introducing Metriks

Tue, 06 Mar 2012 10:22:00 -0800

I was very inspired by Coda Hale’s Metrics Metrics Everywhere talk at CodeConf 2011 and have spent a lot of time over the past year thinking about it. After seeing rack-statsd and how it kept important process stats in the proctitle, I wanted the same thing for the background tasks that run Papertrail.

I hadn’t been able to find a metrics library for ruby that provided the calculations I was looking for, so I decided to experiment with creating one myself.

The end result was an API for measurement that I’m really proud of. For example, to calculate how much work a process is doing, use a meter to measure how many times an event has happened by calling the mark() method on the meter:

def perform(job)
  Metriks.meter('tasks').mark
  # the work
end

The meter provides methods to give a 1, 5 and 15 minute average rate-per-second. The process title can be updated in with the rate returned by one_minute_average() in another thread:

meter = Metriks.meter('tasks')
loop do
  $0 = "worker: #{meter.one_minute_average.to_i} tasks/sec"
  sleep 5
end

…which will give you the output from ps ax that looks like this:

22665 ?        S     17:09 worker: 273 tasks/sec

Once you are tracking those metrics in-process it becomes very easy to start sending them to remote services in all sorts of ways.

The library is called Metriks, an experiment in creating a ruby metrics library with a simple interface and the ability to send the metrics to a number of services.

What sort of stuff are we tracking?

Error rates, database insertion times, cache hits vs misses, messages-per-second processed by workers.

Overview

The main components of the library are the metrics and reporters.

Metrics are responsible for doing a specific kind of measurement
Reporters are responsible for sending metrics to a specific destination

Today you can send to Graphite, Librato Metrics and a log file.

Here’s a quick review of what it’s like to use it and what the important pieces of the library are. It isn’t a huge amount of code, so please check it out.

If you have any questions or comments, feel free to say hi on twitter.

What does it look like to use it?

Using a meter to track web requests

To track the number of requests per second a rack app was doing but didn’t care about timing info, use a Metriks::Meter which can be created by calling Metriks.meter('name').

Here’s a very simple example of what it would look like to track the number of requests per second a rack app was doing.

class MetriksMiddleware < Rack::Middleware
  def initialize(app)
    @app = app
  end
  def call(env)
    Metriks.meter('rack.requests').mark
    @app.call(env)
  end
end

Sending that metric to Librato Metrics could get you a pretty graph looking like this:

Using a timer to measure how long a method takes to run

To track how long it took to run a method, use a Metriks::Timer which can be created with Metriks.timer('name').

To time how long it took to run a fib() method, all it takes is:

def fib(n)
  n < 2 ? n : fib(n-1) + fib(n-2)
end

Metriks.timer('fib.time').time do
  puts fib(10)
end

Sending that metric to Librato Metrics could get you a pretty graph looking like this:

Try it

To install the gem just add this to your Gemfile:

gem 'metriks'

The source is available on GitHub.

Metrics supported

Meter: used to measure the rate that something is happening (number of times per second a method is called).
Timer: used to measure how long it takes to perform something. Also contains a meter to track how many times it’s happening.
Counter: used to keep track of how many times something has happened since the process started. This is mostly used by the other metrics and isn’t often used directly.

Meter

Meters are used to keep track of a rate of an action (how many times per second it happens).

To mark when an action is performed:

Metriks.meter('calls').mark

Timer

Timers are used to keep track of how long it takes for an action to take. It also contains a Meter in it to track how often it happens.

To measure how long an action takes:

Metriks.timer('fib.duration').time do
  fib(10)
end

It’s also possible to use it without making it a block:

timer = Metriks.timer('fib.duration').time
fib(10)
timer.stop

Counter

Counters are used to keep track of an absolute number. They can be incremented and decremented. This metric is generally used as the basis for other metrics instead of being one that would be used directly.

To increment:

Metriks.counter('calls').increment

Reporters

Reporters take a Registry and report the metrics to a remote store.

For a detailed overview of the reporter API, it’s available on the wiki.

Metriks::Reporter::Graphite

Sends metrics to graphite on a set interval. It takes a host and port of the carbon agent as required arguments. Example:

Metriks::Reporter::Graphite.new('localhost', 3309).start

Metriks::Reporter::LibratoMetrics

Send metrics to Librato Metrics on a specified interval. It takes the API credentials as two required arguments: email and token. Example:

Metriks::Reporter::LibratoMetrics.new('user@metriks.local', '186dbe1cf215').start

Metriks::Reporter::Logger

Sends metrics to a logger on a specified interval. Example:

logger = Logger.new('log/metrics.log')
Metriks::Reporter::Logger.new(:logger => logger).start

The main reason behind this reporter was that I wanted to be able to aggregate the metrics collected by multiple processes on the same system before they were sent to Librato Metrics similarly to how StatsD does. To facilitate that, I created a Papertrail webhook receiver that took the logs, parsed the metrics, and submitted them to Librato Metrics. The work resulted in a Sinatra app I’ve posted on GitHub at metriks_log_webhook.

Metriks::Reporter::ProcTitle

Being inspired by rack-statsd I realized there are many metrics that are deep in my processes that would be very interesting to keep track of how my workers are running.

This reporter isn’t really like the others. It reports metrics by updating your proctitle so you can see select metrics when you run ps aux.

Because space in the process title is limited, it requires configuration to specify what metrics are reported.

Example usage:

reporter = Metriks::Reporter::ProcTitle.new
reporter.add 'reqs', 'sec' do
  Metriks.meter('rack.requests').one_minute_rate
end
reporter.start

It would allow you to see the metric when you run ps ax:

22665 ?        S     17:09 thin reqs: 273.3/sec

Implementation Details

Metriks is thread-safe. It uses a combination of mutexes and the atomic gem. Using atomic reduces the need for mutexes without sacrificing thread safety.

It uses the hitimes gem to get high granularity timing data without having to call Time.now.to_f frequently.

Metriks doesn’t tie the gathering of metrics to how they are reported. This allows for swapping out where metrics are reported to without having to change any of the instrumentation.

The metrics classes themselves are mostly ports of the metrics from Coda Hale’s Java metrics library.

Thanks

Thanks to Troy Davis, Joe Ruscio and Mathias Meyer for their help reviewing drafts of this post.

Make your library a better citizen

Sat, 27 Mar 2010 14:52:36 -0700

I’ve recently ran into a case where I wanted the Rails logger to be at :debug level, but really didn’t care about the debug output from the Hoptoad plugin. It kept giving a big XML dump every time it reported an exception which just added noise to the log file that wasn’t relevant.

I’ve found many plugins including Dash (may it rest in peace) and Hoptoad who would steal the logger from Rails and reference that internally.

Here’s the logger in hoptoad:

# Look for the Rails logger currently defined
def logger
  if defined?(Rails.logger)
    Rails.logger
  elsif defined?(RAILS_DEFAULT_LOGGER)
    RAILS_DEFAULT_LOGGER
  end
end

Many times it’s useful to run your staging environment (or even production) with debug logging enabled, but the downside was that now all of these plugins would be logging at that level as well.

One little change that plugin authors can start to do to help the rest of us out is make sure you #dup the logger before you grab a copy.

def logger
  @logger ||= if defined?(Rails.logger)
    Rails.logger.dup
  elsif defined?(RAILS_DEFAULT_LOGGER)
    RAILS_DEFAULT_LOGGER.dup
  end
end

This would allow us to then say:

Hoptoad.logger.level = Logger::WARN

and escape all of the noise from plugins that we don’t care about.

Much thanks to Bruce Williams for first proposing this trick.

PSA: Doing less is more with system and exec

Wed, 20 Jan 2010 14:01:49 -0800

I’ve come across a lot of cases where people take an array of arguments and turn it into a string before passing them to system or exec. I want to spread the news that it isn’t needed and that we can save ourselves from bugs in the future with a little less code.

I don’t mean to pick on defunkt specifically — it’s a pattern I see all the time, but this example is one I had available:

def self.perform(*args)
  script = args.join(' ')
  puts "$ #{script}"
  Open3.popen3(args.join(' ')) do |stdin, stdout, stderr|
    puts stdout.read.inspect
  end
end

You can see the code on GitHub here.

What is Open3.popen3 really doing? It calls a bunch of stuff, like IO::pipe, but in the end, it calls exec with the same arguments that were passed to it:

exec(*cmd)

You can see the whole source for popen3 here.

What happens if we pass a multi-word argument to perform?

ShellJob.perform('rm', '/Library/Keyboard Layouts/Qwerty.bundle')

The arguments are joined and turn into:

"rm /Library/Keyboard Layouts/Qwerty.bundle"

When this is passed to the ruby exec method, the results are parsed with the ruby shell argument parser and it ends up with a child process holding an ARGV of:

["rm", "/Library/Keyboard", "Layouts/Qwerty.bundle"]

…but this isn’t what we wanted!

To understand the basics of what is going on, we have to understand the underlying call that the ruby interpreter calls: execv(3):

int
execv(const char *path, char *const argv[]);

The argv[] array that is passed into execv(3) is copied into the child process as ARGV. Handy isn’t it?

The problem is, there is no version of the C function that takes a single char * of all of the arguments and Does The Right Thing. Because of this, the ruby interpreter has to fake it, using an approximation of how the shell parses arguments.

But there is a better way.

From the documentation for Kernel#exec (emphasis mine):

Replaces the current process by running the given external command. If exec is given a single argument, that argument is taken as a line that is subject to shell expansion before being executed. If multiple arguments are given, the second and subsequent arguments are passed as parameters to command with no shell expansion.

What’s great is, in this case (and in a lot of them), we actually already have an array with all of the arguments in it.

So, we can actually just change the popen3 line to say:

Open3.popen3(*args) do |stdin, stdout, stderr|

and everything will work the way we want.

You can see the full code on GitHub here.

Making it easy to run a single test

Fri, 15 Jan 2010 15:48:10 -0800

In the course of normal development I find myself focusing on specific tests that I want to make sure work properly before moving on to testing the entire test suite.

There is a really great argument to test/unit called --name which will allow you to specify the test to run.

The test/unit rake tasks provide the TESTOPTS environment variable as a means to pass options to the tests runner. To run a specific test we can add our --name option to TESTOPTS like this:

$ rake test:units TEST=test/unit/user_test.rb TESTOPTS="--name=test_should_create_user"

The --name option even takes a regular expression, so we can even do this:

$ rake test:units TEST=test/unit/user_test.rb TESTOPTS="--name='/create_user/'"

Because it’s a pain in the ass to remember the option as well as doing the right amount of escaping and quoting, I created a simple rake task that you can have run before your real test tasks to set TESTOPTS for you. It looks in the TESTNAME environment variable and if it exists, sets TESTOPTS with the correct value.

To pull this off, you can just put the following in lib/tasks/test_name.rake:

namespace :test do
  task :populate_testopts do
    if ENV['TESTNAME'].present?
      ENV['TESTOPTS']  = ENV['TESTOPTS'] ? "#{ENV['TESTOPTS']} " : ''
      ENV['TESTOPTS'] += "--name=#{ENV['TESTNAME'].inspect}"
    end    
  end
end

%w(test:units test:functionals test:integration).each do |task_name|
  Rake::Task[task_name].prerequisites << 'test:populate_testopts'
end

You can find the gist here.

The only thing tricky about this code is that we go and stick an entry in the prerequisites array that each Rake::Task has to make sure that it runs our environment filter code before it runs the task itself.

Once we’ve done that, we can run the tests we want with:

$ rake test:units TEST=test/unit/user_test.rb TESTNAME='/create_user/'

Quick tip for up-to-date Scout graphs

Thu, 07 Jan 2010 16:34:00 -0800

One of the things that’s always made me sad when using Scout has been having to refresh the page to reload the graphs.

Fortunately amcharts, the charting engine used by Scout, has the ability to do refreshing.

Here’s a nice little bookmarklet to make the Scout graphs refresh every 60 seconds.

Drag this link: Scout Reload

To install the bookmarklet, drag the “Scout Reload” link to your bookmark bar.

To use it, click on the bookmarklet when you are on a Scout graph page.

For more hints on how to install bookmarklets, you can see how to install the Delicious bookmarklet here.

What is it doing?

Amcharts provides all sorts of great functionality, including a simple refresh mechanism.

What we do is update the XML configuration via javascript with this chunk:

<settings>
  <data_reloading>
    <interval>60</interval>
    <show_preloader>false</show_preloader>
    <reset_period>true</reset_period>
  </data_reloading>
</settings>

To send that chunk of XML to the chart is very strait forward. We just get a reference to the DOM object that is the chart and call setSettings on it, passing it the XML we want:

$("#amstock").get(0).setSettings(xml_settings_string);

Abusing HTTParty for a Tender client

Wed, 06 Jan 2010 21:22:05 -0800

We all know how great Tender is and had a chance to play with their great API while writing a tool to send out an email every morning with any pending issues.

They’ve done some really great stuff with it, especially with their use of URI Templates.

If you haven’t played with URI Templates before, an example of their JSON with a template in it looks like:

{"site_href": "http://api.tenderapp.com/{site_permalink}"}

which, with the Addressable gem would allow us to say:

>> require 'addressable/template'
>> tmpl = Addressable::Template.new('http://api.tenderapp.com/{site_permalink}')
>> tmpl.expand('site_permalink' => 'help').to_s
=> http://api.tenderapp.com/help

To make things nice and strait forward, Tender follows the convention of using _href as the suffix for any key that contains a template. I was able to use this along with a little magic I snuck into Hash to make my code that much prettier.

All that was required to expand the templates was a little module:

module JsonHelpers
  def href(key, opts = {})
    Addressable::Template.new(self["#{key}_href"]).expand(opts).to_s
  end
end

which I was able to mix in to any Hash that was returned:

# Make the JSON a litte bit more fun to work with
def self.add_json_helpers(data)
  case data
  when Hash
    data.send(:extend, TenderSummary::JsonHelpers)
    data.each { |_, value| add_json_helpers(value) }
  when Array
    data.each { |elem| add_json_helpers(elem) }
  end
  data
end

and then tell HTTParty to use it by specifying a custom parser:

module TenderSummary
  class TenderApi
    include HTTParty

    headers  'Accept' => 'application/vnd.tender-v1+json'
    format   :json
    parser   Proc.new { |b| add_json_helpers(Crack::JSON.parse(b)) }

    # ...

With all this done, it made it very simple to generate the URLs to the resources I wanted access to.

# assuming `site` holds the JSON returned from
# 'http://api.tenderapp.com/{site_permalink}'
discussion_url = site.href(:discussions, :state => :pending)

You can see the entire class of TenderApi on GitHub.

Tracking initial memory usage by file in Ruby

Wed, 30 Dec 2009 11:21:00 -0800

I’ve found that as a project progresses, the initial memory usage of a Rails application seems to grow more and more.

The more time I spend trying to track down memory leaks (or just pieces of code that use more memory than they should) the more I realize that it’s a fairly imprecise science. I’ve had the best luck using tools to give me a good idea of where to start poking around. From there it’s just a matter of looking at the code and finding what silly things people are doing.

If I wanted to see what was contributing to the large memory footprint of an application on startup, tracking how much memory was allocated during each require would give me a good place to start.

The code to do this is amazingly strait forward:

module RequireTracking
  def require(*args)
    start_size = GC.allocated_size
    super
  ensure
    $require_stats[args.first] += (GC.allocated_size - start_size)
  end
end

Object.send(:include, RequireTracking)
Kernel.send(:include, RequireTracking)

The entire implementation is available as a gist on GitHub.

The GC.allocated_size method is included in the RailsBench GC patch which is part of the Ruby Enterprise Edition interpreter.

One thing to understand is this is only tracking how much memory was allocated but not how much was freed. This will cause these statistics to include memory that was temporarily allocated and then no longer referenced. This can be useful because even temporarily using lots of memory can negatively impact startup time.

Another aspect to understand is the numbers we are tracking are what are normally called “self + children” in profilers. This means that all memory allocated by a file as well as anything allocated by files that are required from it are included in the statistics. This results in the same memory being counted multiple times, but is useful in understanding the total memory implications of requiring a file.

Running this on one of the projects I was working on found this little gem:

class Webster
  DICTIONARY = File.open(File.join(File.dirname(__FILE__), 'words')) do |file|
    file.readlines.collect {|each| each.chomp}
  end

  def random_word
    DICTIONARY[rand(DICTIONARY.size)]
  end
end

You can find the source on GitHub here.

This would be a prime candidate for refactoring if you are worried about your memory usage.

Add NewRelic instrumentation for ThinkingSphinx

Tue, 29 Dec 2009 17:11:00 -0800

NewRelic provides a really great mechanism in their plugin to instrument just about anything.

One of the things I found when analyzing actions in NewRelic was that all of the time that was being spent in the ThinkingSphinx methods were being attributed to the template instead of the model. As we all know, mis-attribution of time spent can make tracking down trouble spots in your code much more difficult.

It ends up that all that is required to start tracking the time you are searching in ThinkingSphinx is a couple calls to add_method_tracer:

  add_method_tracer :search, 'ActiveRecord/#{self.name}/search'
  add_method_tracer :search, 'ActiveRecord/search', :push_scope => false
  add_method_tracer :search, 'ActiveRecord/all', :push_scope => false

You can see the full code here.

Once you’ve required the code, you’ll start to see the #search and #search_count methods show up in your Performance Breakdowns:

Isn’t that sweet?

Update: NewRelic has some great documentation for Custom Metric Collection if you want to do more.