class ScoutApm::TrackedRequest

Constants

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.

BACKTRACE_BLACKLIST
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.

Attributes

annotations[R]

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
call_counts[RW]

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.

context[R]

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

headers[R]

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

instant_key[RW]

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)

name_override[RW]

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.

recorder[R]

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

root_layer[R]

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

transaction_id[R]

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

Public Class Methods

new(agent_context, store) click to toggle source
# File lib/scout_apm/tracked_request.rb, line 59
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
  ignore_request! if @recorder.nil?
end

Public Instance Methods

acknowledge_children!() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 442
def acknowledge_children!
  if @ignoring_children > 0
    @ignoring_children -= 1
  end
end
annotate_request(hsh) click to toggle source

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.

# File lib/scout_apm/tracked_request.rb, line 263
def annotate_request(hsh)
  @annotations.merge!(hsh)
end
backtrace_threshold() click to toggle source

Grab backtraces more aggressively when running in dev trace mode

# File lib/scout_apm/tracked_request.rb, line 208
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) click to toggle source
# File lib/scout_apm/tracked_request.rb, line 162
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!() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 218
def capture_mem_delta!
  @mem_delta = mem_usage - @mem_start
end
current_layer() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 157
def current_layer
  @layers.last
end
ensure_background_worker() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 380
def ensure_background_worker
  agent = ScoutApm::Agent.instance
  agent.start
rescue => e
  true
end
error!() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 268
def error!
  @error = true
end
error?() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 272
def error?
  @error
end
finalized?() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 228
def finalized?
  @layers.none?
end
ignore_children!() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 438
def ignore_children!
  @ignoring_children += 1
end
ignore_request!() click to toggle source

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 @ignoring_depth counter) so we know when to report that the class was “reported”, and ready to be recreated for the next request.

# File lib/scout_apm/tracked_request.rb, line 466
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?() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 448
def ignoring_children?
  @ignoring_children > 0
end
ignoring_recorded?() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 495
def ignoring_recorded?
  @ignoring_depth <= 0
end
ignoring_request?() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 483
def ignoring_request?
  @ignoring_request
end
ignoring_start_layer() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 487
def ignoring_start_layer
  @ignoring_depth += 1
end
ignoring_stop_layer() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 491
def ignoring_stop_layer
  @ignoring_depth -= 1
end
instant?() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 280
def instant?
  return false if ignoring_request?

  instant_key
end
job?() click to toggle source

This request is a job transaction iff it has a 'Job' layer Use this only during recording

# File lib/scout_apm/tracked_request.rb, line 363
def job?
  layer_finder.job != nil
end
layer_finder() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 374
def layer_finder
  @layer_finder ||= LayerConverters::FindLayerByType.new(self)
end
layer_insignificant?(layer) click to toggle source

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.

# File lib/scout_apm/tracked_request.rb, line 190
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() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 499
def logger
  @agent_context.logger
end
mem_usage() click to toggle source

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?

# File lib/scout_apm/tracked_request.rb, line 214
def mem_usage
  ScoutApm::Instruments::Process::ProcessMemory.new(@agent_context).rss
end
prepare_to_dump!() click to toggle source

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)

# File lib/scout_apm/tracked_request.rb, line 510
def prepare_to_dump!
  @call_set = nil
  @store = nil
  @recorder = nil
  @agent_context = nil
end
real_request!() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 140
def real_request!
  @real_request = true
end
real_request?() click to toggle source

Have we seen a “controller” or “job” layer so far?

# File lib/scout_apm/tracked_request.rb, line 145
def real_request?
  @real_request
end
record!() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 296
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])

  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!() click to toggle source

Persist the Request

# File lib/scout_apm/tracked_request.rb, line 290
def recorded!
  @recorded = true
end
recorded?() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 405
def recorded?
  return ignoring_recorded? if ignoring_request?

  @recorded
end
restore_from_dump!() click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 519
def restore_from_dump!
  @agent_context = ScoutApm::Agent.instance.context
  @recorder = @agent_context.recorder
  @store = @agent_context.store
end
set_headers(headers) click to toggle source
# File lib/scout_apm/tracked_request.rb, line 276
def set_headers(headers)
  @headers = headers
end
start_layer(layer) click to toggle source
# File lib/scout_apm/tracked_request.rb, line 78
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) click to toggle source

Run at the beginning of the whole request

# File lib/scout_apm/tracked_request.rb, line 235
def start_request(layer)
  @root_layer = layer unless @root_layer # capture root layer
end
stop_layer() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 94
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() click to toggle source

Run at the end of the whole request

  • Send the request off to be stored

# File lib/scout_apm/tracked_request.rb, line 242
def stop_request
  @stopping = true

  if @recorder
    @recorder.record!(self)
  end
end
stopping?() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 250
def stopping?
  @stopping
end
unique_name() click to toggle source

Only call this after the request is complete

# File lib/scout_apm/tracked_request.rb, line 389
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) click to toggle source

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

# File lib/scout_apm/tracked_request.rb, line 203
def update_call_counts!(layer)
  @call_set[layer.name].update!(layer.desc)
end
web?() click to toggle source

This request is a web transaction iff it has a 'Controller' layer Use this only during recording

# File lib/scout_apm/tracked_request.rb, line 369
def web?
  layer_finder.controller != nil
end

Private Instance Methods

apply_name_override() click to toggle source
# File lib/scout_apm/tracked_request.rb, line 527
def apply_name_override
  return unless name_override

  scope_layer = layer_finder.scope
  if scope_layer
    scope_layer.name = name_override
  end
end