class GraphQL::Metrics::Tracer

Constants

GRAPHQL_GEM_ANALYZE_MULTIPLEX_KEY
GRAPHQL_GEM_ANALYZE_QUERY_KEY
GRAPHQL_GEM_EXECUTE_MULTIPLEX_KEY

NOTE: These constants come from the graphql ruby gem and are in “chronological” order based on the phases of execution of the graphql-ruby gem, though old versions of the gem aren't always consistent about this (see github.com/rmosolgo/graphql-ruby/issues/3393). Most of them can be run multiple times when multiplexing multiple queries.

GRAPHQL_GEM_EXECUTE_QUERY_KEY
GRAPHQL_GEM_LEXING_KEY
GRAPHQL_GEM_PARSING_KEY
GRAPHQL_GEM_TRACING_FIELD_KEYS
GRAPHQL_GEM_VALIDATION_KEY
PreContext

Public Instance Methods

trace(key, data) { || ... } click to toggle source
# File lib/graphql/metrics/tracer.rb, line 22
def trace(key, data, &block)
  # NOTE: Context doesn't exist yet during lexing, parsing.
  context = data[:query]&.context
  skip_tracing = context&.fetch(GraphQL::Metrics::SKIP_GRAPHQL_METRICS_ANALYSIS, false)
  return yield if skip_tracing

  case key
  when GRAPHQL_GEM_EXECUTE_MULTIPLEX_KEY
    return capture_multiplex_start_time(&block)
  when GRAPHQL_GEM_LEXING_KEY
    return capture_lexing_time(&block)
  when GRAPHQL_GEM_PARSING_KEY
    return capture_parsing_time(&block)
  when GRAPHQL_GEM_VALIDATION_KEY
    return capture_validation_time(context, &block)
  when GRAPHQL_GEM_ANALYZE_MULTIPLEX_KEY
    # Ensures that we reset potentially long-lived PreContext objects between multiplexs. We reset at this point
    # since all parsing and validation will be done by this point, and a GraphQL::Query::Context will exist.
    pre_context.reset
    return yield
  when GRAPHQL_GEM_ANALYZE_QUERY_KEY
    return capture_analysis_time(context, &block)
  when GRAPHQL_GEM_EXECUTE_QUERY_KEY
    capture_query_start_time(context, &block)
  when *GRAPHQL_GEM_TRACING_FIELD_KEYS
    return yield if context[SKIP_FIELD_AND_ARGUMENT_METRICS]
    return yield unless GraphQL::Metrics.timings_capture_enabled?(data[:query].context)

    context_key = case key
    when GRAPHQL_GEM_TRACING_FIELD_KEY
      GraphQL::Metrics::INLINE_FIELD_TIMINGS
    when GRAPHQL_GEM_TRACING_LAZY_FIELD_KEY
      GraphQL::Metrics::LAZY_FIELD_TIMINGS
    end

    trace_field(context_key, data, &block)
  else
    return yield
  end
end

Private Instance Methods

capture_analysis_time(context) { || ... } click to toggle source
# File lib/graphql/metrics/tracer.rb, line 148
def capture_analysis_time(context)
  ns = context.namespace(CONTEXT_NAMESPACE)

  timed_result = GraphQL::Metrics.time(ns[MULTIPLEX_START_TIME_MONOTONIC]) { yield }

  ns[ANALYSIS_START_TIME_OFFSET] = timed_result.time_since_offset
  ns[ANALYSIS_DURATION] = timed_result.duration

  timed_result.result
end
capture_lexing_time() { || ... } click to toggle source
# File lib/graphql/metrics/tracer.rb, line 95
def capture_lexing_time
  # GraphQL::Query#result fires `lex` before the `execute_multiplex` event, so sometimes
  # `pre_context.multiplex_start_time_monotonic` isn't set.
  lexing_offset_time = pre_context.multiplex_start_time_monotonic || GraphQL::Metrics.current_time_monotonic
  timed_result = GraphQL::Metrics.time(lexing_offset_time) { yield }

  pre_context.lexing_start_time_offset = timed_result.start_time
  pre_context.lexing_duration = timed_result.duration

  timed_result.result
end
capture_multiplex_start_time() { || ... } click to toggle source
# File lib/graphql/metrics/tracer.rb, line 88
def capture_multiplex_start_time
  pre_context.multiplex_start_time = GraphQL::Metrics.current_time
  pre_context.multiplex_start_time_monotonic = GraphQL::Metrics.current_time_monotonic

  yield
end
capture_parsing_time() { || ... } click to toggle source
# File lib/graphql/metrics/tracer.rb, line 107
def capture_parsing_time
  # GraphQL::Query#result fires `parse` before the `execute_multiplex` event, so sometimes
  # `pre_context.multiplex_start_time_monotonic` isn't set.
  parsing_offset_time = pre_context.multiplex_start_time_monotonic || GraphQL::Metrics.current_time_monotonic
  timed_result = GraphQL::Metrics.time(parsing_offset_time) { yield }

  pre_context.parsing_start_time_offset = timed_result.start_time
  pre_context.parsing_duration = timed_result.duration

  timed_result.result
end
capture_query_start_time(context) { || ... } click to toggle source
# File lib/graphql/metrics/tracer.rb, line 159
def capture_query_start_time(context)
  ns = context.namespace(CONTEXT_NAMESPACE)
  ns[QUERY_START_TIME] = GraphQL::Metrics.current_time
  ns[QUERY_START_TIME_MONOTONIC] = GraphQL::Metrics.current_time_monotonic

  yield
end
capture_validation_time(context) { || ... } click to toggle source

Also consolidates parsing timings (if any) from the `pre_context`

# File lib/graphql/metrics/tracer.rb, line 120
def capture_validation_time(context)
  # Queries may already be lexed and parsed before execution (whether a single query or multiplex).
  # If we don't have those values, use some sane defaults.
  if pre_context.lexing_duration.nil?
    pre_context.lexing_start_time_offset = pre_context.multiplex_start_time
    pre_context.lexing_duration = 0.0
  end
  if pre_context.parsing_duration.nil?
    pre_context.parsing_start_time_offset = pre_context.multiplex_start_time
    pre_context.parsing_duration = 0.0
  end

  timed_result = GraphQL::Metrics.time(pre_context.multiplex_start_time_monotonic) { yield }

  ns = context.namespace(CONTEXT_NAMESPACE)

  ns[MULTIPLEX_START_TIME] = pre_context.multiplex_start_time
  ns[MULTIPLEX_START_TIME_MONOTONIC] = pre_context.multiplex_start_time_monotonic
  ns[LEXING_START_TIME_OFFSET] = pre_context.lexing_start_time_offset
  ns[LEXING_DURATION] = pre_context.lexing_duration
  ns[PARSING_START_TIME_OFFSET] = pre_context.parsing_start_time_offset
  ns[PARSING_DURATION] = pre_context.parsing_duration
  ns[VALIDATION_START_TIME_OFFSET] = timed_result.time_since_offset
  ns[VALIDATION_DURATION] = timed_result.duration

  timed_result.result
end
pre_context() click to toggle source
# File lib/graphql/metrics/tracer.rb, line 81
def pre_context
  # NOTE: This is used to store timings from lexing, parsing, validation, before we have a context to store
  # values in. Uses thread-safe Concurrent::ThreadLocalVar to store a set of values per thread.
  @pre_context ||= Concurrent::ThreadLocalVar.new(PreContext.new)
  @pre_context.value
end
trace_field(context_key, data) { || ... } click to toggle source
# File lib/graphql/metrics/tracer.rb, line 167
def trace_field(context_key, data)
  ns = data[:query].context.namespace(CONTEXT_NAMESPACE)
  query_start_time_monotonic = ns[GraphQL::Metrics::QUERY_START_TIME_MONOTONIC]

  timed_result = GraphQL::Metrics.time(query_start_time_monotonic) { yield }

  path_excluding_numeric_indicies = data[:path].select { |p| p.is_a?(String) }
  ns[context_key][path_excluding_numeric_indicies] ||= []
  ns[context_key][path_excluding_numeric_indicies] << {
    start_time_offset: timed_result.time_since_offset, duration: timed_result.duration
  }

  timed_result.result
end