Class: ScoutApm::TrackedRequest

Inherits:
Object
  • Object
show all
Defined in:
lib/scout_apm/tracked_request.rb

Constant Summary collapse

REQUEST_TYPES =

When we see these layers, it means a real request is going through the system. We toggle a flag to turn on some slightly more expensive instrumentation (backtrace collection and the like) that would be too expensive in situations where the framework is constantly churning. We see that on Sidekiq.

["Controller", "Job"]
AUTO_INSTRUMENT_TIMING_THRESHOLD =

Layers of type 'AutoInstrument' are not recorded if their total_call_time doesn't exceed this threshold. AutoInstrument layers are frequently of short duration. This throws out this deadweight that is unlikely to be optimized.

5/1_000.0
BACKTRACE_BLACKLIST = 
["Controller", "Job"]

Instance Attribute Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(agent_context, store) ⇒ TrackedRequest

units = seconds



61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
 
# File 'lib/scout_apm/tracked_request.rb', line 61

def initialize(agent_context, store)
  @agent_context = agent_context
  @store = store #this is passed in so we can use a real store (normal operation) or fake store (instant mode only)
  @layers = []
  @call_set = Hash.new { |h, k| h[k] = CallSet.new }
  @annotations = {}
  @ignoring_children = 0
  @context = Context.new(agent_context)
  @root_layer = nil
  @error = false
  @stopping = false
  @instant_key = nil
  @mem_start = mem_usage
  @recorder = agent_context.recorder
  @real_request = false
  @transaction_id = ScoutApm::Utils::TransactionId.new.to_s
  # The thread this request was created on. ActionController::Live copies the
  # raw Thread.current locals (including :scout_request) into its streaming
  # child thread, which would otherwise cause two threads to share and race
  # on one TrackedRequest. RequestManager uses this to detect an inherited
  # request and give the child its own instead. See RequestManager.find.
  @creating_thread_id = Thread.current.object_id
  ignore_request! if @recorder.nil?
end

Instance Attribute Details

#annotations ⇒ Object (readonly)

As we go through a request, instrumentation can mark more general data into the Request Known Keys:

:uri - the full URI requested by the user
:queue_latency - how long a background Job spent in the queue before starting processing


25
26
27
 
# File 'lib/scout_apm/tracked_request.rb', line 25

def annotations
  @annotations
end

#call_counts ⇒ Object

This maintains a lookup hash of Layer names and call counts. It's used to trigger fetching a backtrace on n+1 calls. Note that layer names might not be Strings - can alse be Utils::ActiveRecordMetricName. Also, this would fail for layers with same names across multiple types.



34
35
36
 
# File 'lib/scout_apm/tracked_request.rb', line 34

def call_counts
  @call_counts
end

#context ⇒ Object (readonly)

Context is application defined extra information. (ie, which user, what is their email/ip, what plan are they on, what locale are they using, etc) See documentation for examples on how to set this from a before_filter



15
16
17
 
# File 'lib/scout_apm/tracked_request.rb', line 15

def context
  @context
end

#creating_thread_id ⇒ Object (readonly)

The object_id of the Thread that created this request. Used to detect a TrackedRequest that was inherited by a different thread (e.g. an ActionController::Live streaming thread) rather than created for it.



89
90
91
 
# File 'lib/scout_apm/tracked_request.rb', line 89

def creating_thread_id
  @creating_thread_id
end

#headers ⇒ Object (readonly)

Headers as recorded by rails Can be nil if we never reach a Rails Controller



29
30
31
 
# File 'lib/scout_apm/tracked_request.rb', line 29

def headers
  @headers
end

#instant_key ⇒ Object

if there's an instant_key, pass the transaction trace on for immediate reporting (in addition to the usual background aggregation) this is set in the controller instumentation (ActionControllerRails3Rails4 according)



38
39
40
 
# File 'lib/scout_apm/tracked_request.rb', line 38

def instant_key
  @instant_key
end

#name_override ⇒ Object

If specified, an override for the name of the request. If unspecified, the name is determined from the name of the Controller or Job layer.



45
46
47
 
# File 'lib/scout_apm/tracked_request.rb', line 45

def name_override
  @name_override
end

#recorder ⇒ Object (readonly)

An object that responds to record!(TrackedRequest) to store this tracked request



41
42
43
 
# File 'lib/scout_apm/tracked_request.rb', line 41

def recorder
  @recorder
end

#root_layer ⇒ Object (readonly)

The first layer registered with this request. All other layers will be children of this layer.



19
20
21
 
# File 'lib/scout_apm/tracked_request.rb', line 19

def root_layer
  @root_layer
end

#transaction_id ⇒ Object (readonly)

A unique, but otherwise meaningless String to identify this request. UUID



48
49
50
 
# File 'lib/scout_apm/tracked_request.rb', line 48

def transaction_id
  @transaction_id
end

Instance Method Details

#acknowledge_children! ⇒ Object 



470
471
472
473
474
 
# File 'lib/scout_apm/tracked_request.rb', line 470

def acknowledge_children!
  if @ignoring_children > 0
    @ignoring_children -= 1
  end
end

#annotate_request(hsh) ⇒ Object

As we learn things about this request, we can add data here. For instance, when we know where Rails routed this request to, we can store that scope info. Or as soon as we know which URI it was directed at, we can store that.

This data is internal to ScoutApm, to add custom information, use the Context api.



280
281
282
 
# File 'lib/scout_apm/tracked_request.rb', line 280

def annotate_request(hsh)
  @annotations.merge!(hsh)
end

#backtrace_threshold ⇒ Object

Grab backtraces more aggressively when running in dev trace mode



225
226
227
 
# File 'lib/scout_apm/tracked_request.rb', line 225

def backtrace_threshold
  @agent_context.dev_trace_enabled? ? 0.05 : 0.5 # the minimum threshold in seconds to record the backtrace for a metric.
end

#capture_backtrace?(layer) ⇒ Boolean

Returns:

  • (Boolean) 


179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
 
# File 'lib/scout_apm/tracked_request.rb', line 179

def capture_backtrace?(layer)
  return if ignoring_request?

  # A backtrace has already been recorded. This happens with autoinstruments as
  # the partial backtrace is set when creating the layer.
  return false if layer.backtrace

  # Never capture backtraces for this kind of layer. The backtrace will
  # always be 100% framework code.
  return false if BACKTRACE_BLACKLIST.include?(layer.type)

  # Only capture backtraces if we're in a real "request". Otherwise we
  # can spend lot of time capturing backtraces from the internals of
  # Sidekiq, only to throw them away immediately.
  return false unless real_request?

  # Capture any individually slow layer.
  return true if layer.total_exclusive_time > backtrace_threshold

  # Capture any layer that we've seen many times. Captures n+1 problems
  return true if @call_set[layer.name].capture_backtrace?

  # Don't capture otherwise
  false
end

#capture_mem_delta! ⇒ Object 



235
236
237
 
# File 'lib/scout_apm/tracked_request.rb', line 235

def capture_mem_delta!
  @mem_delta = mem_usage - @mem_start
end

#current_layer ⇒ Object

Grab the currently running layer. Useful for adding additional data as we learn it. This is useful in ActiveRecord instruments, where we start the instrumentation early, and gradually learn more about the request that actually happened as we go (for instance, the # of records found, or the actual SQL generated).

Returns nil in the case there is no current layer. That would be normal for a completed TrackedRequest



174
175
176
 
# File 'lib/scout_apm/tracked_request.rb', line 174

def current_layer
  @layers.last
end

#ensure_background_worker ⇒ Object

Ensure the background worker thread is up & running - a fallback if other detection doesn't achieve this at boot.



408
409
410
411
412
413
 
# File 'lib/scout_apm/tracked_request.rb', line 408

def ensure_background_worker
  agent = ScoutApm::Agent.instance
  agent.start
rescue => e
  true
end

#error! ⇒ Object

This request had an exception. Mark it down as an error



285
286
287
 
# File 'lib/scout_apm/tracked_request.rb', line 285

def error!
  @error = true
end

#error? ⇒ Boolean

Returns:

  • (Boolean) 


289
290
291
 
# File 'lib/scout_apm/tracked_request.rb', line 289

def error?
  @error
end

#finalized? ⇒ Boolean

Are we finished with this request? We're done if we have no layers left after popping one off

Returns:

  • (Boolean) 


245
246
247
 
# File 'lib/scout_apm/tracked_request.rb', line 245

def finalized?
  @layers.none?
end

#ignore_children! ⇒ Object

Enable this when you would otherwise double track something interesting. This came up when we implemented InfluxDB instrumentation, which is more specific, and useful than the fact that InfluxDB happens to use Net::HTTP internally

When enabled, new layers won't be added to the current Request, and calls to stop_layer will be ignored.

Do not forget to turn if off when leaving a layer, it is the instrumentation's task to do that.

When you use this in code, be sure to use it in this order:

start_layer ignore_children -> call acknowledge_children stop_layer

If you don't call it in this order, it's possible to get out of sync, and have an ignored start and an actually-executed stop, causing layers to get out of sync



466
467
468
 
# File 'lib/scout_apm/tracked_request.rb', line 466

def ignore_children!
  @ignoring_children += 1
end

#ignore_request! ⇒ Object

At any point in the request, calling code or instrumentation can call ignore_request! to immediately stop recording any information about new layers, and delete any existing layer info. This class will still exist, and respond to methods as normal, but record! won't be called, and no data will be recorded.

We still need to keep track of the current layer depth (via "reported", and ready to be recreated for the next request.



494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
 
# File 'lib/scout_apm/tracked_request.rb', line 494

def ignore_request!
  return if @ignoring_request

  # Set instance variable
  @ignoring_request = true

  # Store data we'll need
  @ignoring_depth = @layers.length

  # Clear data
  @layers = []
  @root_layer = nil
  @call_set = nil
  @annotations = {}
  @instant_key = nil
end

#ignoring_children? ⇒ Boolean

Returns:

  • (Boolean) 


476
477
478
 
# File 'lib/scout_apm/tracked_request.rb', line 476

def ignoring_children?
  @ignoring_children > 0
end

#ignoring_recorded? ⇒ Boolean

Returns:

  • (Boolean) 


523
524
525
 
# File 'lib/scout_apm/tracked_request.rb', line 523

def ignoring_recorded?
  @ignoring_depth <= 0
end

#ignoring_request? ⇒ Boolean

Returns:

  • (Boolean) 


511
512
513
 
# File 'lib/scout_apm/tracked_request.rb', line 511

def ignoring_request?
  @ignoring_request
end

#ignoring_start_layer ⇒ Object 



515
516
517
 
# File 'lib/scout_apm/tracked_request.rb', line 515

def ignoring_start_layer
  @ignoring_depth += 1
end

#ignoring_stop_layer ⇒ Object 



519
520
521
 
# File 'lib/scout_apm/tracked_request.rb', line 519

def ignoring_stop_layer
  @ignoring_depth -= 1
end

#instant? ⇒ Boolean

Returns:

  • (Boolean) 


297
298
299
300
301
 
# File 'lib/scout_apm/tracked_request.rb', line 297

def instant?
  return false if ignoring_request?

  instant_key
end

#job? ⇒ Boolean

True iff this request has a 'Job' layer. Only reliable during recording -- see #web? for why.

Returns:

  • (Boolean) 


384
385
386
 
# File 'lib/scout_apm/tracked_request.rb', line 384

def job?
  layer_finder.job != nil
end

#layer_count ⇒ Object 



91
92
93
 
# File 'lib/scout_apm/tracked_request.rb', line 91

def layer_count
  @layers.size
end

#layer_finder ⇒ Object 



402
403
404
 
# File 'lib/scout_apm/tracked_request.rb', line 402

def layer_finder
  @layer_finder ||= LayerConverters::FindLayerByType.new(self)
end

#layer_insignificant?(layer) ⇒ Boolean

Returns true if the total call time of AutoInstrument layers exceeds AUTO_INSTRUMENT_TIMING_THRESHOLD and records a Histogram of insignificant / significant layers by file name.

Returns:

  • (Boolean) 


207
208
209
210
211
212
213
214
215
216
217
 
# File 'lib/scout_apm/tracked_request.rb', line 207

def layer_insignificant?(layer)
  result = false # default is significant
  if layer.type == 'AutoInstrument'
    if layer.total_call_time < AUTO_INSTRUMENT_TIMING_THRESHOLD
      result = true # not significant
    end
    # 0 = not significant, 1 = significant
    @agent_context.auto_instruments_layer_histograms.add(layer.file_name, (result ? 0 : 1))
  end
  result
end

#logger ⇒ Object 



527
528
529
 
# File 'lib/scout_apm/tracked_request.rb', line 527

def logger
  @agent_context.logger
end

#mem_usage ⇒ Object

This may be in bytes or KB based on the OSX. We store this as-is here and only do conversion to MB in Layer Converters. XXX: Move this to environment?



231
232
233
 
# File 'lib/scout_apm/tracked_request.rb', line 231

def mem_usage
  ScoutApm::Instruments::Process::ProcessMemory.new(@agent_context).rss
end

#prepare_to_dump! ⇒ Object

Actually go fetch & make-real any lazily created data. Clean up any cleverness in objects. Makes this object ready to be Marshal Dumped (or otherwise serialized)



538
539
540
541
542
543
 
# File 'lib/scout_apm/tracked_request.rb', line 538

def prepare_to_dump!
  @call_set = nil
  @store = nil
  @recorder = nil
  @agent_context = nil
end

#real_request! ⇒ Object 



157
158
159
 
# File 'lib/scout_apm/tracked_request.rb', line 157

def real_request!
  @real_request = true
end

#real_request? ⇒ Boolean

Have we seen a "controller" or "job" layer so far?

Returns:

  • (Boolean) 


162
163
164
 
# File 'lib/scout_apm/tracked_request.rb', line 162

def real_request?
  @real_request
end

#record! ⇒ Object

Convert this request to the appropriate structure, then report it into the peristent Store object



313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
 
# File 'lib/scout_apm/tracked_request.rb', line 313

def record!
  recorded!

  return if ignoring_request?

  # If we didn't have store, but we're trying to record anyway, go
  # figure that out. (this happens in Remote Agent scenarios)
  restore_from_dump! if @agent_context.nil?

  # Bail out early if the user asked us to ignore this uri
  # return if @agent_context.ignored_uris.ignore?(annotations[:uri])
  if @agent_context.sampling.drop_request?(self)
    logger.debug("Dropping request due to sampling")
    return
  end

  apply_name_override

  @agent_context.transaction_time_consumed.add(unique_name, root_layer.total_call_time)

  context.add(:transaction_id => transaction_id)

  # Make a constant, then call converters.dup.each so it isn't inline?
  converters = {
    :histograms => LayerConverters::Histograms,
    :metrics => LayerConverters::MetricConverter,
    :errors => LayerConverters::ErrorConverter,
    :allocation_metrics => LayerConverters::AllocationMetricConverter,
    :queue_time => LayerConverters::RequestQueueTimeConverter,
    :job => LayerConverters::JobConverter,
    :db => LayerConverters::DatabaseConverter,
    :external_service => LayerConverters::ExternalServiceConverter,

    :slow_job => LayerConverters::SlowJobConverter,
    :slow_req => LayerConverters::SlowRequestConverter,

    # This is now integrated into the slow_job and slow_req converters, so that
    # we get the exact same set of traces either way. We can call it
    # directly when we move away from the legacy trace styles.
    # :traces => LayerConverters::TraceConverter,
  }

  walker = LayerConverters::DepthFirstWalker.new(self.root_layer)
  converter_instances = converters.inject({}) do |memo, (slug, klass)|
    instance = klass.new(@agent_context, self, layer_finder, @store)
    instance.register_hooks(walker)
    memo[slug] = instance
    memo
  end
  walker.walk
  converter_results = converter_instances.inject({}) do |memo, (slug,i)|
    memo[slug] = i.record!
    memo
  end

  @agent_context.extensions.run_transaction_callbacks(converter_results,context,layer_finder.scope)

  # If there's an instant_key, it means we need to report this right away
  if web? && instant?
    converter = converters.find{|c| c.class == LayerConverters::SlowRequestConverter}
    trace = converter.call
    ScoutApm::InstantReporting.new(trace, instant_key).call
  end

  if web? || job?
    ensure_background_worker
  end
end

#recorded! ⇒ Object

Persist the Request



307
308
309
 
# File 'lib/scout_apm/tracked_request.rb', line 307

def recorded!
  @recorded = true
end

#recorded? ⇒ Boolean

Have we already persisted this request? Used to know when we should just create a new one (don't attempt to add data to an already-recorded request). See RequestManager

Returns:

  • (Boolean) 


433
434
435
436
437
 
# File 'lib/scout_apm/tracked_request.rb', line 433

def recorded?
  return ignoring_recorded? if ignoring_request?

  @recorded
end

#restore_from_dump! ⇒ Object

Go re-fetch the store based on what the Agent's official one is. Used after hydrating a dumped TrackedRequest



547
548
549
550
551
 
# File 'lib/scout_apm/tracked_request.rb', line 547

def restore_from_dump!
  @agent_context = ScoutApm::Agent.instance.context
  @recorder = @agent_context.recorder
  @store = @agent_context.store
end

#set_headers(headers) ⇒ Object 



293
294
295
 
# File 'lib/scout_apm/tracked_request.rb', line 293

def set_headers(headers)
  @headers = headers
end

#start_layer(layer) ⇒ Object 



95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
 
# File 'lib/scout_apm/tracked_request.rb', line 95

def start_layer(layer)
  # If we're already stopping, don't do additional layers
  return if stopping?

  return if ignoring_children?

  return ignoring_start_layer if ignoring_request?

  start_request(layer) unless @root_layer

  if REQUEST_TYPES.include?(layer.type)
    real_request!
  end
  @layers.push(layer)
end

#start_request(layer) ⇒ Object

Run at the beginning of the whole request

  • Capture the first layer as the root_layer


252
253
254
 
# File 'lib/scout_apm/tracked_request.rb', line 252

def start_request(layer)
  @root_layer = layer unless @root_layer # capture root layer
end

#stop_layer ⇒ Object 



111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
 
# File 'lib/scout_apm/tracked_request.rb', line 111

def stop_layer
  # If we're already stopping, don't do additional layers
  return if stopping?

  return if ignoring_children?

  return ignoring_stop_layer if ignoring_request?

  layer = @layers.pop

  # Safeguard against a mismatch in the layer tracking in an instrument.
  # This class works under the assumption that start & stop layers are
  # lined up correctly. If stop_layer gets called twice, when it should
  # only have been called once you'll end up with this error.
  if layer.nil?
    logger.warn("Error stopping layer, was nil. Root Layer: #{@root_layer.inspect}")
    stop_request
    return
  end

  layer.record_stop_time!
  layer.record_allocations!

  # Must follow layer.record_stop_time! as the total_call_time is used to determine if the layer is significant.
  return if layer_insignificant?(layer)

  # Check that the parent exists before calling a method on it, since some threading can get us into a weird state.
  # this doesn't fix that state, but prevents exceptions from leaking out.
  parent = @layers[-1]
  if parent
    parent.add_child(layer)
  end

  # This must be called before checking if a backtrace should be collected as the call count influences our capture logic.
  # We call `#update_call_counts in stop layer to ensure the layer has a final desc. Layer#desc is updated during the AR instrumentation flow.
  update_call_counts!(layer)
  if capture_backtrace?(layer)
    layer.capture_backtrace!
  end


  if finalized?
    stop_request
  end
end

#stop_request ⇒ Object

Run at the end of the whole request

  • Send the request off to be stored


259
260
261
262
263
264
265
 
# File 'lib/scout_apm/tracked_request.rb', line 259

def stop_request
  @stopping = true

  if @recorder
    @recorder.record!(self)
  end
end

#stopping? ⇒ Boolean

Returns:

  • (Boolean) 


267
268
269
 
# File 'lib/scout_apm/tracked_request.rb', line 267

def stopping?
  @stopping
end

#unique_name ⇒ Object

Only call this after the request is complete



417
418
419
420
421
422
423
424
425
426
427
428
 
# File 'lib/scout_apm/tracked_request.rb', line 417

def unique_name
  return nil if ignoring_request?

  @unique_name ||= begin
                     scope_layer = LayerConverters::FindLayerByType.new(self).scope
                     if scope_layer
                       scope_layer.legacy_metric_name
                     else
                       :unknown
                     end
                   end
end

#update_call_counts!(layer) ⇒ Object

Maintains a lookup Hash of call counts by layer name. Used to determine if we should capture a backtrace.



220
221
222
 
# File 'lib/scout_apm/tracked_request.rb', line 220

def update_call_counts!(layer)
  @call_set[layer.name].update!(layer.desc)
end

#web? ⇒ Boolean

True iff this request has a 'Controller' layer.

Only reliable during recording; returns false mid-request even for a real web request. #layer_finder walks root_layer's child tree, but layers are attached to that tree only in #stop_layer (via add_child), not in #start_layer. Controller/Job are top-level spans, so they stop last -- meaning web?/job? only resolve as the request unwinds into recording. (Negative results aren't memoized, so an early false doesn't poison a later check.)

Returns:

  • (Boolean) 


397
398
399
 
# File 'lib/scout_apm/tracked_request.rb', line 397

def web?
  layer_finder.controller != nil
end