tracer.rb in graphql-metrics-4.1.0

- old
+ new

@@ -1,52 +1,50 @@
 # frozen_string_literal: true
 
 module GraphQL
   module Metrics
     class Tracer
-      # NOTE: These constants come from the graphql ruby gem.
-      GRAPHQL_GEM_EXECUTE_MULTIPLEX_KEY = 'execute_multiplex'
-      GRAPHQL_GEM_PARSING_KEY = 'parse'
+      # 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. Most of them can be run multiple times when multiplexing multiple queries.
+      GRAPHQL_GEM_LEXING_KEY = 'lex' # may not trigger if the query is passed in pre-parsed
+      GRAPHQL_GEM_PARSING_KEY = 'parse' # may not trigger if the query is passed in pre-parsed
+      GRAPHQL_GEM_EXECUTE_MULTIPLEX_KEY = 'execute_multiplex' # wraps everything below this line; only run once
       GRAPHQL_GEM_VALIDATION_KEY = 'validate'
-      GRAPHQL_GEM_ANALYZE_MULTIPLEX_KEY = 'analyze_multiplex'
+      GRAPHQL_GEM_ANALYZE_MULTIPLEX_KEY = 'analyze_multiplex' # wraps all `analyze_query`s; only run once
       GRAPHQL_GEM_ANALYZE_QUERY_KEY = 'analyze_query'
       GRAPHQL_GEM_EXECUTE_QUERY_KEY = 'execute_query'
       GRAPHQL_GEM_TRACING_FIELD_KEYS = [
         GRAPHQL_GEM_TRACING_FIELD_KEY = 'execute_field',
         GRAPHQL_GEM_TRACING_LAZY_FIELD_KEY = 'execute_field_lazy'
       ]
 
       def trace(key, data, &block)
         # NOTE: Context doesn't exist yet during lexing, parsing.
-        possible_context = data[:query]&.context
-
-        skip_tracing = possible_context&.fetch(GraphQL::Metrics::SKIP_GRAPHQL_METRICS_ANALYSIS, false)
+        context = data[:query]&.context
+        skip_tracing = context&.fetch(GraphQL::Metrics::SKIP_GRAPHQL_METRICS_ANALYSIS, false)
         return yield if skip_tracing
 
-        # NOTE: Not all tracing events are handled here, but those that are are handled in this case statement in
-        # chronological order.
         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_EXECUTE_MULTIPLEX_KEY
+          return capture_multiplex_start_time(&block)
         when GRAPHQL_GEM_VALIDATION_KEY
-          context = possible_context
           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
-          context = possible_context
           return capture_analysis_time(context, &block)
         when GRAPHQL_GEM_EXECUTE_QUERY_KEY
-          context = possible_context
           capture_query_start_time(context, &block)
         when *GRAPHQL_GEM_TRACING_FIELD_KEYS
-          return yield if data[:query].context[SKIP_FIELD_AND_ARGUMENT_METRICS]
+          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
@@ -64,11 +62,13 @@
 
       PreContext = Struct.new(
         :multiplex_start_time,
         :multiplex_start_time_monotonic,
         :parsing_start_time_offset,
-        :parsing_duration
+        :parsing_duration,
+        :lexing_start_time_offset,
+        :lexing_duration
       ) do
         def reset
           self[:multiplex_start_time] = nil
           self[:multiplex_start_time_monotonic] = nil
           self[:parsing_start_time_offset] = nil
@@ -88,10 +88,22 @@
         pre_context.multiplex_start_time_monotonic = GraphQL::Metrics.current_time_monotonic
 
         yield
       end
 
+      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
+
       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 }
@@ -102,24 +114,28 @@
         timed_result.result
       end
 
       # Also consolidates parsing timings (if any) from the `pre_context`
       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?
-          # Queries may already be parsed before execution (whether a single query or multiplex).
-          # If we don't have a parsing start time, use the multiplex start time.
           pre_context.parsing_start_time_offset = pre_context.multiplex_start_time
-
-          # If we don't have a duration, consider parsing to have been instantaneous.
           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
 