Sequel & Sinatra Instrumentation

readme.md

Instruments

Instruments enables out-of-the-box instrumentation on database & HTTP activities.

Usage

Provide an object that will take a hash as an argument.

Instruments.set_logger(Kernel, :puts)

Sinatra

require "sinatra"
require "instruments"

instrument_routes
Instruments.set_logger(Kernel, :puts)

get "/hello/:name" do
  "hello #{params[:name]}"
end

Now when you hit this endpoint, you will see the following in your log stream:

action="http-request" method="get" route="/hello/:name" status=200 elapsed=0.001

Sequel

require "sequel"
require "instruments"

instrument_routes
Instruments.set_logger(Kernel, :puts)

DB.loggers << Logger.new($stdout) #sequel requires this :(
DB.class.send(:include, Sequel::Instrumentation)
DB[:events].count

Will produce:

action=select elapsed_time=0.1 sql="select count(*) from events"

TODO

• rest-client
• queue_classic
• redis

Links

• sinatra/sinatra#499
• jeremyevans/sequel#465

Contributors

• @konstantinhaase
• @mmcgrana
• @nzoschke
• @jeremyevans

instruments.rb

module Instruments
  def self.set_logger(l, m)
    @logger = l
    @method = m
  end

  def self.logger
    @logger
  end

  def self.method
    @method
  end

  if defined?(::Sinatra)
    module ::Sinatra
      module Instrumentation
        def route(verb, action, *)
          condition {@instrumented_route = action}
          super
        end

        def instrument_routes
          before do
            @start_request = Time.now
          end
          after do
            t = Integer((Time.now - @start_request)*1000)
            Instruments.logger.send(Instruments.method, {
              :app => "your-app",
              :action => "http-request",
              :route => @instrumented_route,
              :elapsed => t,
              :method => env["REQUEST_METHOD"].downcase,
              :status => response.status
            }.merge(params))
          end
        end
      end
    end
  end

  if defined?(::Sequel)
    module ::Sequel
      module Instrumentation
        def log_duration(t, sql)
          t = Integer(t*=1000)
          if t > DB_ERROR_THREASHOLD
            Instruments.logger.send(Instruments.method, {:error => true, :action => action(sql), :elapsed => t, :sql => sql})
          elsif t > DB_WARN_THREASHOLD
            Instruments.logger.send(Instruments.method, {:warn => true, :action => action(sql), :elapsed => t, :sql => sql})
          else
            Instruments.logger.send(Instruments.method, {:info => true, :action => action(sql), :elapsed => t, :sql => sql})
          end
        end

        def log_exception(e, sql)
          Instruments.logger.send(Instruments.method, {:exception => e.class, :sql => sql})
        end

        def action(sql)
          sql[/(\w+){1}/].downcase
        end
      end
    end
  end
end

mem_stat.rb

module Memstat
  extend self

  def puts
    "memory=#{real_mem_size}"
  end

  def real_mem_size
    mb = `ps -o rsz #{$$}`.split("\n")[1].to_f / 1024.0
    mb = mb.round(-2) # nearest 100 (i.e. 60.round(-2) == 100)
    "#{mb}MB"
  end

end

Neat!

A few comments:

• Does the Sequel logging come through paramaterized like the Sinatra web logs, like select * from events where data->'password' = $1, so that queries are normalized and don't contain sensitive information?
• What about including e.g. method=get in the Sinatra web logs?
• The elapsed_time key is pretty verbose - have you considered just elapsed?
• I think it's worth thinking about log levels and how they interact with the interface:
  • We've found log levels in general to be of questionable use, and in any event to be well-handled vai the normalized data path, e.g. {:level => "debug", ..., which terminal logging clients can either chose to emit as data (level=debug), in a special cased way ([DEBUG] foo=bar), or not at all based on the level itself.
  • I'll want to inflate all data from this instrumentation with my own, like release=v273 deploy=production. For this a single interface is most convenient: Insturments.logger = MyApp.method(:log). See here and here for an example of this inflation pattern.
• I'll have to give this a shot on Tines or Exprd...

This looks pretty good. A few comments:

• The action method is simplistic (will display "with" for any query using CTEs), but I don't see an easy way around that.
• You don't want to require just "sequel/database", as I make no guarantees that that can be done safely (even if it works at present). Require 'sequel/core' instead.
• Instruments.error.warn should be Instruments.logger.error, right?

SyntaxError: /Users/csquared/heroku/lights-heartbeat/instruments.rb:47: syntax error, unexpected keyword_elsif
elsif t > DB_WARN_THREASHOLD
this is from the dangling
:sql =>
on line 44