queue_time_logger.rb

# combination of https://gist.github.com/daveyeu/4960893
# and https://gist.github.com/jasonrclark/d82a1ea7695daac0b9ee
class QueueTimeLogger
  attr_reader :app

  def initialize(app, options = {})
    @app = app
  end

  def call(env)
    now = Time.now.to_f

    # Delete Heroku's queue time header because it's incorrect and useless
    env.delete("HTTP_X_HEROKU_QUEUE_WAIT_TIME")

    microseconds = (now * 1_000_000).to_i
    env["HTTP_X_MIDDLEWARE_START"] = "t=#{microseconds}"

    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

      env["HTTP_X_QUEUE_TIME"] = "t=#{queue_time_microseconds}"
    end

    app.call(env)
  end
end

This is a combination of https://gist.github.com/daveyeu/4960893 (stolen from https://twitter.com/daveyeu/status/302433766050238464) and https://gist.github.com/jasonrclark/d82a1ea7695daac0b9ee (given to us by a new relic rep).

Jesus! This isn't good - I mean what this reveals!

@chalkers - did you add it to your app? When we added it to ours, we saw the actual queue times; scary stuff!

This is great, putting it in production as we speak, but note that there's a small time skew between the routing mesh and your dyno. So the queue time may be incorrect in both directions. So you need to adjust the code to at least not report negative numbers. Bonus feature is to return the queue time in a header.

# https://gist.github.com/a-warner/f5db30857ed3423cea79
# combination of https://gist.github.com/daveyeu/4960893
# and https://gist.github.com/jasonrclark/d82a1ea7695daac0b9ee
class QueueTimeLogger
  attr_reader :app

  def initialize(app, options = {})
    @app = app
  end

  def call(env)
    now = Time.now.to_f

    # Delete Heroku's queue time header because it's incorrect and useless
    env.delete("HTTP_X_HEROKU_QUEUE_WAIT_TIME")

    microseconds = (now * 1_000_000).to_i
    env["HTTP_X_MIDDLEWARE_START"] = "t=#{microseconds}"

    perf_headers = {}
    if (request_start = env["HTTP_X_REQUEST_START"])
      request_start_microseconds = request_start.gsub("t=", "").to_i * 1_000
      queue_time_microseconds = [ microseconds - request_start_microseconds, 0 ].max
      env["HTTP_X_QUEUE_TIME"] = "t=#{queue_time_microseconds}"

      queue_time_milliseconds = (queue_time_microseconds / 1_000).to_i
      perf_headers["X-Queue-Time"] = queue_time_milliseconds.to_s
    end

    status, headers, body = app.call(env)
    [ status, headers.merge(perf_headers), body ]
  end
end

Also, should we really be getting rid of HTTP_X_HEROKU_QUEUE_WAIT_TIME or adding it to the queue time?

It looks like the queueing adds about 100% time on to the request - https://heroku.newrelic.com/public/charts/ePidiWZzahz

@chalkers: it will depend heavily on your context, double the number of dynos and watch the impact

I'm trying to port it to python. What am I doing wrong?

__author__ = 'jbastos'
import time

QUEUE_WAIT = "HTTP_X_HEROKU_QUEUE_WAIT_TIME"
QUEUE_TIME = "HTTP_X_QUEUE_TIME"
REQ_START = "HTTP_X_REQUEST_START"
MIDDLEWARE = "HTTP_X_MIDDLEWARE_START"


class NewRelicMiddleware:
    def __init__(self, app):
        self.app = app

    def __call__(self, environ, start_response):
        ms = int(time.time() * 1000000)
        if QUEUE_WAIT in environ:
            del environ[QUEUE_WAIT]
        environ[MIDDLEWARE] = "t=%d" % ms
        if REQ_START in environ:
            req_start_ms = int(environ[REQ_START]) * 1000
            qtime_ms = max(ms - req_start_ms, 0)
            environ[QUEUE_TIME] = "t=%d" % qtime_ms
        return self.app(environ, start_response)

Thank you very much for this! Our actual queue times are horrible, instead of the 1-5 ms on average that was shown in NewRelic before, it is actually around 300 ms on average, but with spikes upto 7 seconds average during a minute. The max queue times for a lot of requests are way worse than these averages. We nearly doubled the number of dynos now, but still getting queue time spikes around 1 second average during a minute sometimes. The average response time excluding the queue time is 20 ms.

This explains the response times we were seeing using pingdom, for which we contacted heroku support a couple of months ago, but got no useful response. So thanks again for bringing this to our attention.

I'm trying to add this to an app on Heroku but I'm getting this error on every request:

2013-02-18T11:25:55+00:00 app[web.1]: TypeError (instance of Hash needs to have method `marshal_load'):
2013-02-18T11:25:55+00:00 app[web.1]:   lib/queue_time_logger.rb:28:in `call'

I can't replicate this locally running in development, stage or production environments. It only seems to happen at Heroku (in stage environment).

I've tried using config.middleware.insert 0, QueueTimeLogger and also use QueueTimeLogger in config.ru in various places, all of them cause this error at Heroku and are fine locally. I'm running 1.9.3-p327 at heroku and locally through RVM.

I'm totally stumped, anyone else experienced this or have any ideas ?

Hmm, if I remove everything inside the call method so it just returns app.call(env) I still get that error. So it's something elsewhere in my app (despite other middleware being fine). Oh well

@marcroberts - have you tried adding this with a rails initializer? We were doing something like:

config/initializers/queue_time_logger.rb

Rails.configuration.middleware.insert_after 'Rack::Lock', QueueTimeLogger

Or is this a sinatra/rack app?

Hey all - check out https://github.com/RapGenius/heroku-true-relic, which is a gem version of this gist. We'll try to keep that up to date as we get more information about how best to track dyno-level queuing.

@dblock Thanks for the tip on not reporting negative queue time numbers; I incorporated that into the gem.

Thanks @a-warner but it was a totally unrelated issue (I had been trying out ruby 2.0.0 preview and switching back to 1.9.3 had broken the session cookie).

The gem looks great (I had started writing one myself but I'll give up on that now), thanks

do i need to modify my new relic or heroku configuration for the gem to work out of the box? i've just deployed this to a staging app I have running on the cedar stack with new relic standard, and am throwing a ton of requests at it with ab, but am seeing 0 queueing.