Class: ActionDispatch::MiddlewareStack::RackTimer

Inherits:
Object
  • Object
show all
Defined in:
lib/rack_timer/stack.rb

Overview

this class will wrap around each Rack-based middleware and take timing snapshots of how long each middleware takes to execute

Constant Summary collapse

LogThreshold =

modify this environment variable to see more or less output

ENV.has_key?('RACK_TIMER_LOG_THRESHOLD') ? ENV['RACK_TIMER_LOG_THRESHOLD'].to_f : 1.0

Instance Method Summary collapse

Constructor Details

#initialize(app) ⇒ RackTimer

Returns a new instance of RackTimer.



11
12
13
 
# File 'lib/rack_timer/stack.rb', line 11

def initialize(app)
  @app = app
end

Instance Method Details

#call(env) ⇒ Object 



15
16
17
18
19
20
 
# File 'lib/rack_timer/stack.rb', line 15

def call(env)
  env = incoming_timestamp(env)
  status, headers, body = @app.call env
  env = outgoing_timestamp(env)
  [status, headers, body]
end

#incoming_timestamp(env) ⇒ Object 



22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
 
# File 'lib/rack_timer/stack.rb', line 22

def incoming_timestamp(env)
  if env.has_key?("MIDDLEWARE_TIMESTAMP") # skip over the first middleware
    elapsed_time = (Time.now.to_f - env["MIDDLEWARE_TIMESTAMP"][1].to_f) * 1000 
    if elapsed_time > LogThreshold # only log if took greater than LogThreshold
      Rails.logger.info "Rack Timer (incoming) -- #{env["MIDDLEWARE_TIMESTAMP"][0]}: #{elapsed_time} ms"
    end
  elsif 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: #{(Time.now.to_f * 1000000).to_i - queue_start_time} microseconds"
  end
  env["MIDDLEWARE_TIMESTAMP"] = [@app.class.to_s, Time.now]
  env
end

#outgoing_timestamp(env) ⇒ Object 



40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
 
# File 'lib/rack_timer/stack.rb', line 40

def outgoing_timestamp(env)
  if env.has_key?("MIDDLEWARE_TIMESTAMP")
    elapsed_time = (Time.now.to_f - env["MIDDLEWARE_TIMESTAMP"][1].to_f) * 1000
    if 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"              
      else
        Rails.logger.info "Rack Timer (outgoing) -- #{@app.class.to_s}: #{elapsed_time} ms"
      end
    end
  end
  env["MIDDLEWARE_TIMESTAMP"] = [nil, Time.now]
  env
end