Sinatra - How to calculate the response time for every request for stats purposes?

Question

I would like to measure the execution time of each Sinatra route including the complete request/response cycle duration and then send this metrics to a Graphite server.

My first approach was to use the Rack::Runtime and then fetch the values I needed from the response headers in the Sinatra after filter but I discovered that this filter is actually executed before the response is completely sent to the client.

So not only I cannot access many response informations in the after block, I also cannot use this block to send the metrics to Graphite in any other way because they wouldn't reflect the real response time.

I've read in other topics that a possible approach is to create a Rack middleware to wrap the application and execute the benchmark and I ended with something like this:

class GraphiteRoutesReporter

  def initialize(app)
    @app = app
  end

  def call(env)
    start_time = Time.now
    status, headers, body  = @app.call(env)
    time_taken = (1000 * (Time.now - start_time))

    # send #{time_taken} to my stats server

    [status, headers, body]
  end
end

Which I can include in config.ru and seems like it's working fine.

But my worries are about this code messing with the core Rack request chain and I am worry that I am making incorrect use of the Sinatra public API.

Which is the proper way to get the full response time of a Sinatra request?

Answer 1

If I were to find a solution for a non-business-critical reason (so we speak about a "fun"-scenario) I would regularly "parse" (awk) the default log output of sinatra where the response time is included (at the very end: 0.1093 seconds in the example - if I'm not wrong)

179.24.226.1 - felixb [22/Aug/2016:13:30:46 +0200] "GET /index HTTP/1.0" 200 11546 0.1093

Which might bring me to the idea of implement a simple Logger who does whatever should happen with the output (yes, thats a hack).

But that said, your approach looks fine to me, just make sure to offload the # send #{time_taken} to my stats server - you dont want to make your users wait because your Graphite is too hard to get the teeth in fast.

Also if it is about profiling your web-app/server, take a look at https://github.com/MiniProfiler/rack-mini-profiler .