Class: RackMonitor::ProcessUtilization

Inherits:
Object
  • Object
show all
Defined in:
lib/rack_monitor.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

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.



98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
 
# File 'lib/rack_monitor.rb', line 98

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]
    @hostname = options[:hostname] || `hostname -s`.chomp
  end
end

Instance Attribute Details

#active_time ⇒ Object

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



131
132
133
 
# File 'lib/rack_monitor.rb', line 131

def active_time
  @active_time
end

#domain ⇒ Object

the app’s domain name - shown in proctitle



116
117
118
 
# File 'lib/rack_monitor.rb', line 116

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.



123
124
125
 
# File 'lib/rack_monitor.rb', line 123

def horizon
  @horizon
end

#requests ⇒ Object

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



127
128
129
 
# File 'lib/rack_monitor.rb', line 127

def requests
  @requests
end

#revision ⇒ Object

the currently running git revision as a 7-sha



119
120
121
 
# File 'lib/rack_monitor.rb', line 119

def revision
  @revision
end

#total_requests ⇒ Object

total requests processed by this worker process since it started



134
135
136
 
# File 'lib/rack_monitor.rb', line 134

def total_requests
  @total_requests
end

#worker_number ⇒ Object

the unicorn worker number



137
138
139
 
# File 'lib/rack_monitor.rb', line 137

def worker_number
  @worker_number
end

Instance Method Details

#average_response_time ⇒ Object

average response time since the horizon in milliseconds



166
167
168
 
# File 'lib/rack_monitor.rb', line 166

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

#call(env) ⇒ Object

Rack entry point.



260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
 
# File 'lib/rack_monitor.rb', line 260

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) }
  [status, headers, body]
end

#first_request ⇒ Object

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



171
172
173
174
 
# File 'lib/rack_monitor.rb', line 171

def first_request
  reset_horizon
  record_worker_number
end

#horizon_time ⇒ Object

the amount of time since the horizon



140
141
142
 
# File 'lib/rack_monitor.rb', line 140

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.



146
147
148
 
# File 'lib/rack_monitor.rb', line 146

def idle_time
  horizon_time - active_time
end

#percentage_active ⇒ Object

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



151
152
153
 
# File 'lib/rack_monitor.rb', line 151

def percentage_active
  (active_time / horizon_time) * 100
end

#percentage_idle ⇒ Object

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



156
157
158
 
# File 'lib/rack_monitor.rb', line 156

def percentage_idle
  (idle_time / horizon_time) * 100
end

#procline ⇒ Object

the generated procline



193
194
195
196
197
198
199
200
201
202
203
 
# File 'lib/rack_monitor.rb', line 193

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) ⇒ Object

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



207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
 
# File 'lib/rack_monitor.rb', line 207

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

  $0 = procline

  if @stats
    @stats.timing("unicorn.#{@hostname}.response_time", diff * 1000)
    if suffix = status_suffix(status)
      @stats.increment "unicorn.#{Gitio.host}.status_code.#{status_suffix(status)}"
    end
    if @track_gc && GC.time > 0
      @stats.timing "unicorn.#{@hostname}.gc.time", GC.time / 1000
      @stats.count  "unicorn.#{@hostname}.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



184
185
186
187
188
189
190
 
# File 'lib/rack_monitor.rb', line 184

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



161
162
163
 
# File 'lib/rack_monitor.rb', line 161

def requests_per_second
  requests / horizon_time
end

#reset_horizon ⇒ Object

resets the horizon and all dependent variables



177
178
179
180
181
 
# File 'lib/rack_monitor.rb', line 177

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

#status_suffix(status) ⇒ Object 



231
232
233
234
235
236
237
238
 
# File 'lib/rack_monitor.rb', line 231

def status_suffix(status)
  suffix = case status.to_i
    when 404 then :missing
    when 422 then :invalid
    when 503 then :node_down
    when 500 then :error
  end
end