Rack Timer is Rails instrumentation middleware that logs long running middleware, Heroku, request_id, and is adding NewRelic instrumentation to each installed middleware.

rack_timer.rb

# From https://github.com/lukeludwig/rack_timer
# mentioned at http://pulse.sportngin.com/news_article/show/137153
#
# Environment configuration, e.g. heroku.yml:
#
#     RACK_TIMER = true | false                           # instrument middleware?
#     RACK_TIMER_LOG = true | false                       # enable logging for each middleware
#     RACK_TIMER_LOG_THRESHOLD = 100                      # threshold in ms when logs are written
#     RACK_TIMER_NEWRELIC_INSTRUMENTATION = true | false  # enable Newrelic instrumentation
#
module ActionDispatch
  # require "new_relic/agent/instrumentation/controller_instrumentation"
  module NewRelicInstrumentation
    require 'new_relic/agent/instrumentation/rack'
    require 'new_relic/agent/method_tracer'
    
    def self.extended(base)
      # add NewRelic instrumentation to every middleware, except RackTimer
      if base.respond_to?(:instance_method_names) && base.instance_method_names.include?("call")
        base.class_eval do
          # adds an action tracer arround each middleware call method
          # https://newrelic.com/docs/ruby/rack-and-metal-support-in-the-ruby-agent
          include ::NewRelic::Agent::Instrumentation::Rack

          # additionally, adds a method tracer arround call method
          # https://newrelic.com/docs/ruby/ruby-custom-metric-collection#examples
          # http://rubydoc.info/gems/newrelic_rpm/NewRelic/Agent/MethodTracer/ClassMethods:add_method_tracer
          include ::NewRelic::Agent::MethodTracer
          add_method_tracer :call, "Custom/#{name.underscore}/call", {:push_scope => true, :metric => true}
        end
      end
    end
  end

  class MiddlewareStack

    # this class will wrap around each Rack-based middleware and take timing snapshots of how long
    # each middleware takes to execute
    class RackTimer
      include ::NewRelic::Agent::Instrumentation::ControllerInstrumentation
      
      # modify this environment variable to see more or less output
      Enabled             = ENV.has_key?('RACK_TIMER') ? ENV['RACK_TIMER'] == "true" : false
      LogEnabled          = ENV.has_key?('RACK_TIMER_LOG') ? ENV['RACK_TIMER_LOG'] == "true" : false
      LogThreshold        = ENV.has_key?('RACK_TIMER_LOG_THRESHOLD') ? ENV['RACK_TIMER_LOG_THRESHOLD'].to_f : 1.0 # millisecond
      NewRelicEnabled     = ENV.has_key?('RACK_TIMER_NEWRELIC_INSTRUMENTATION') ? ENV['RACK_TIMER_NEWRELIC_INSTRUMENTATION'] == "true" : false

      def initialize(app)
        @app = app
        # @app.class.send(:extend, ActionDispatch::NewRelicInstrumentation) if RackTimer::NewRelicEnabled
      end

      def call(env)
        status, headers, body = nil, nil, nil
        env = incoming_timestamp(env)
        unless RackTimer::NewRelicEnabled
          status, headers, body = @app.call env
        else
          call_with_newrelic(env) do
            status, headers, body = @app.call env
          end
        end
        env = outgoing_timestamp(env)
        [status, headers, body]
      end

      # derived from https://gist.github.com/dblock/4170469
      def call_with_newrelic(env, &block)
        trace_options = {
          :category => :rack,
          :name     => "Custom/#{@app.class.name.underscore}/call",
          :path     => env["REQUEST_PATH"],
          :request  => ::Rack::Request.new(env)
        }

        perform_action_with_newrelic_trace(trace_options) do
          yield
        end
      end

      private
      
      def incoming_timestamp(env)
        now          = Time.now
        microseconds = (now.to_f * 1_000_000).to_i
        if env.has_key?("MIDDLEWARE_TIMESTAMP") # skip over the first middleware
          elapsed_time = (now.to_f - env["MIDDLEWARE_TIMESTAMP"][1].to_f) * 1_000 
          if LogEnabled && elapsed_time > LogThreshold # only log if took greater than LogThreshold
            Rails.logger.info "Rack Timer (incoming) -- #{env["MIDDLEWARE_TIMESTAMP"][0]}: #{elapsed_time} ms at #{microseconds}"
          end
        else
          # we are at the top of the middleware stack here
          if LogEnabled && env.has_key?("HTTP_X_REQUEST_START") or env.has_key?("HTTP_X_QUEUE_START")
            # if we are tracking request queuing time via New Relic's suggested header(s),
            # then lets see how much time was spent in the request queue by taking the difference
            # between Time.now from the start of the first piece of middleware
            # prefer HTTP_X_QUEUE_START over HTTP_X_REQUEST_START in case both exist
            queue_start_time = (env["HTTP_X_QUEUE_START"] || env["HTTP_X_REQUEST_START"]).gsub("t=", "").to_i
            Rails.logger.info "Rack Timer -- Queuing time: #{(now.to_f * 1_000_000).to_i - queue_start_time} microseconds"
            puts "request_id=#{env['HTTP_HEROKU_REQUEST_ID']}"
          end
          
          # The following is a combination of 
          #   https://gist.github.com/daveyeu/4960893 and
          #   https://gist.github.com/jasonrclark/d82a1ea7695daac0b9ee
            
          # delete Heroku's queue time header because it's incorrect and useless
          # https://gist.github.com/a-warner/f5db30857ed3423cea79
          # this is outdated, but we keep it for now!
          env.delete("HTTP_X_HEROKU_QUEUE_WAIT_TIME")
          
          # as we are at the top of the middleware stack, we add a timestamp here
          # for New Relic to recognize when the middleware stack has started.
          # https://support.cloud.engineyard.com/entries/21382793-new-relic-best-practices
          env["HTTP_X_MIDDLEWARE_START"] = "t=#{microseconds}"
          
          # now we can calculate and report the time the request has been queued.
          # it's the time between request start minus now
          if env["HTTP_X_REQUEST_START"]
            # HTTP_X_REQUEST_START is expected by New Relic to have a t= leading
            # but currently doesn't, so it can just get to_i applied.
            request_start_microseconds = env["HTTP_X_REQUEST_START"].to_i * 1_000
            queue_time_microseconds = [microseconds - request_start_microseconds, 0].max

            env["HTTP_X_QUEUE_TIME"] = "t=#{queue_time_microseconds}"
          end
          
          if LogEnabled
            # enable experimental request_id from Heroku router as described in:
            # https://devcenter.heroku.com/articles/http-request-id
            #
            # Add on command line:
            #
            #     $ heroku labs:enable http-request-id -a <app-name>
            #
            # check Heroku router error codes and request_id against the request_id
            # logged in the following call. See follwoing for Heroku error codes:
            # https://devcenter.heroku.com/articles/error-codes#h13-connection-closed-without-response
            Rails.logger.info "Rack Timer -- Middleware start at #{microseconds}, Heroku request_id=#{env['HTTP_HEROKU_REQUEST_ID']}"
          end
        end
        env["MIDDLEWARE_TIMESTAMP"] = [@app.class.to_s, now]
        env
      end

      def outgoing_timestamp(env)
        now = Time.now
        microseconds = (now.to_f * 1_000_000).to_i
        if env.has_key?("MIDDLEWARE_TIMESTAMP")
          elapsed_time = (now.to_f - env["MIDDLEWARE_TIMESTAMP"][1].to_f) * 1_000
          if LogEnabled && elapsed_time > LogThreshold # only log if took greater than LogThreshold
            if env["MIDDLEWARE_TIMESTAMP"][0] and env["MIDDLEWARE_TIMESTAMP"][0] == @app.class.to_s
              # this is the actual elapsed time of the final piece of Middleware (typically routing) AND the actual
              # application's action
              Rails.logger.info "Rack Timer (Application Action) -- #{@app.class.to_s}: #{elapsed_time} ms at #{microseconds}"
            else
              Rails.logger.info "Rack Timer (outgoing) -- #{@app.class.to_s}: #{elapsed_time} ms at #{microseconds}"
            end
          end
        end
        env["MIDDLEWARE_TIMESTAMP"] = [nil, now]
        env
      end
    end

    class Middleware

      # overriding the built-in Middleware.build and adding a RackTimer wrapper class
      def build(app)
        # mixes in New Relic's rack instrumentation if the environment wants to
        if RackTimer::Enabled
          RackTimer.new(klass.new(app, *args, &block))
        else
          klass.new(app, *args, &block)
        end
      end    

    end

    # overriding this in order to wrap the incoming app in a RackTimer, which gives us timing on the final
    # piece of Middleware, which for Rails is the routing plus the actual Application action
    # actionpack/lib/action_dispatch/middleware/stack.rb
    def build(app = nil, &block)
      app ||= block
      raise "MiddlewareStack#build requires an app" unless app
      if RackTimer::Enabled
        middlewares.reverse.inject(RackTimer.new(app)) {|a, e| e.build(a)}
      else
        middlewares.reverse.inject(app) {|a, e| e.build(a)}
      end
    end

  end
end