Class: RackStatsD::ProcessUtilization

Inherits:
Object
  • Object
show all
Defined in:
lib/rack-statsd.rb

Overview

Middleware that tracks the amount of time this process spends processing requests, as opposed to being idle waiting for a connection. Statistics are dumped to rack.errors every 5 minutes.

NOTE This middleware is not thread safe. It should only be used when rack.multiprocess is true and rack.multithread is false.

Defined Under Namespace

Classes: Body

Constant Summary collapse

REQUEST_METHOD = 
'REQUEST_METHOD'.freeze
VALID_METHODS = 
['GET', 'HEAD', 'POST', 'PUT', 'DELETE'].freeze

Instance Attribute Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(app, domain, revision, options = {}) ⇒ ProcessUtilization

Initializes the middleware.

app - The next Rack app in the pipeline. domain - The String domain name the app runs in. revision - The String SHA that describes the current version of code. options - Hash of options.

:window       - The Integer number of seconds before the
                horizon resets.
:stats        - Optional StatsD client.
:hostname     - Optional String hostname. Set to nil
                to exclude.
:stats_prefix - Optional String prefix for StatsD keys.
                Default: "rack"



105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
 
# File 'lib/rack-statsd.rb', line 105

def initialize(app, domain, revision, options = {})
  @app = app
  @domain = domain
  @revision = revision
  @window = options[:window] || 100
  @horizon = nil
  @active_time = nil
  @requests = nil
  @total_requests = 0
  @worker_number = nil
  @track_gc = GC.respond_to?(:time)

  if @stats = options[:stats]
    prefix = [options[:stats_prefix] || :rack]
    if options.has_key?(:hostname)
      prefix << options[:hostname] unless options[:hostname].nil?
    else
      prefix << `hostname -s`.chomp
    end
    @stats_prefix = prefix.join(".")
  end
end

Instance Attribute Details

#active_time ⇒ Object

decimal number of seconds the worker has been active within a request since the horizon time.



144
145
146
 
# File 'lib/rack-statsd.rb', line 144

def active_time
  @active_time
end

#domain ⇒ Object

the app’s domain name - shown in proctitle



129
130
131
 
# File 'lib/rack-statsd.rb', line 129

def domain
  @domain
end

#horizon ⇒ Object

time when we began sampling. this is reset every once in a while so averages don’t skew over time.



136
137
138
 
# File 'lib/rack-statsd.rb', line 136

def horizon
  @horizon
end

#requests ⇒ Object

total number of requests that have been processed by this worker since the horizon time.



140
141
142
 
# File 'lib/rack-statsd.rb', line 140

def requests
  @requests
end

#revision ⇒ Object

the currently running git revision as a 7-sha



132
133
134
 
# File 'lib/rack-statsd.rb', line 132

def revision
  @revision
end

#total_requests ⇒ Object

total requests processed by this worker process since it started



147
148
149
 
# File 'lib/rack-statsd.rb', line 147

def total_requests
  @total_requests
end

#worker_number ⇒ Object

the unicorn worker number



150
151
152
 
# File 'lib/rack-statsd.rb', line 150

def worker_number
  @worker_number
end

Instance Method Details

#average_response_time ⇒ Object

average response time since the horizon in milliseconds



179
180
181
 
# File 'lib/rack-statsd.rb', line 179

def average_response_time
  (active_time / requests.to_f) * 1000
end

#call(env) ⇒ Object

Rack entry point.



298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
 
# File 'lib/rack-statsd.rb', line 298

def call(env)
  @start = Time.now
  GC.clear_stats if @track_gc

  @total_requests += 1
  first_request if @total_requests == 1

  env['process.request_start'] = @start.to_f
  env['process.total_requests'] = total_requests

  # newrelic X-Request-Start
  env.delete('HTTP_X_REQUEST_START')

  status, headers, body = @app.call(env)
  body = Body.new(body) { record_request(status, env) }
  [status, headers, body]
end

#first_request ⇒ Object

called exactly once before the first request is processed by a worker



184
185
186
187
 
# File 'lib/rack-statsd.rb', line 184

def first_request
  reset_horizon
  record_worker_number
end

#horizon_time ⇒ Object

the amount of time since the horizon



153
154
155
 
# File 'lib/rack-statsd.rb', line 153

def horizon_time
  Time.now - horizon
end

#idle_time ⇒ Object

decimal number of seconds this process has been active since the horizon time. This is the inverse of the active time.



159
160
161
 
# File 'lib/rack-statsd.rb', line 159

def idle_time
  horizon_time - active_time
end

#percentage_active ⇒ Object

percentage of time this process has been active since the horizon time.



164
165
166
 
# File 'lib/rack-statsd.rb', line 164

def percentage_active
  (active_time / horizon_time) * 100
end

#percentage_idle ⇒ Object

percentage of time this process has been idle since the horizon time.



169
170
171
 
# File 'lib/rack-statsd.rb', line 169

def percentage_idle
  (idle_time / horizon_time) * 100
end

#procline ⇒ Object

the generated procline



206
207
208
209
210
211
212
213
214
215
216
 
# File 'lib/rack-statsd.rb', line 206

def procline
  "unicorn %s[%s] worker[%02d]: %5d reqs, %4.1f req/s, %4dms avg, %5.1f%% util" % [
    domain,
    revision,
    worker_number.to_i,
    total_requests.to_i,
    requests_per_second.to_f,
    average_response_time.to_i,
    percentage_active.to_f
  ]
end

#record_request(status, env) ⇒ Object

called immediately after a request to record statistics, update the procline, and dump information to the logfile



220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
 
# File 'lib/rack-statsd.rb', line 220

def record_request(status, env)
  now = Time.now
  diff = (now - @start)
  @active_time += diff
  @requests += 1

  $0 = procline

  if @stats
    @stats.timing("#{@stats_prefix}.response_time", diff * 1000)
    if VALID_METHODS.include?(env[REQUEST_METHOD])
      stat = "#{@stats_prefix}.response_time.#{env[REQUEST_METHOD].downcase}"
      @stats.timing(stat, diff * 1000)
    end

    if suffix = status_suffix(status)
      @stats.increment "#{@stats_prefix}.status_code.#{status_suffix(status)}"
    end
    if @track_gc && GC.time > 0
      @stats.timing "#{@stats_prefix}.gc.time", GC.time / 1000
      @stats.count  "#{@stats_prefix}.gc.collections", GC.collections
    end
  end

  reset_horizon if now - horizon > @window
rescue => boom
  warn "ProcessUtilization#record_request failed: #{boom}"
end

#record_worker_number ⇒ Object

extracts the worker number from the unicorn procline



197
198
199
200
201
202
203
 
# File 'lib/rack-statsd.rb', line 197

def record_worker_number
  if $0 =~ /^.* worker\[(\d+)\].*$/
    @worker_number = $1.to_i
  else
    @worker_number = nil
  end
end

#requests_per_second ⇒ Object

number of requests processed per second since the horizon



174
175
176
 
# File 'lib/rack-statsd.rb', line 174

def requests_per_second
  requests / horizon_time
end

#reset_horizon ⇒ Object

resets the horizon and all dependent variables



190
191
192
193
194
 
# File 'lib/rack-statsd.rb', line 190

def reset_horizon
  @horizon = Time.now
  @active_time = 0.0
  @requests = 0
end

#status_suffix(status) ⇒ Object 



249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
 
# File 'lib/rack-statsd.rb', line 249

def status_suffix(status)
  suffix = case status.to_i
    when 200 then :ok
    when 201 then :created
    when 202 then :accepted
    when 301 then :moved_permanently
    when 302 then :found
    when 303 then :see_other
    when 304 then :not_modified
    when 305 then :use_proxy
    when 307 then :temporary_redirect
    when 400 then :bad_request
    when 401 then :unauthorized
    when 402 then :payment_required
    when 403 then :forbidden
    when 404 then :missing
    when 410 then :gone
    when 422 then :invalid
    when 500 then :error
    when 502 then :bad_gateway
    when 503 then :node_down
    when 504 then :gateway_timeout
  end
end