Merge pull request #84 from Shopify/remove-apollo-tracing-spec-support

Remove Apollo tracing spec support

README.md

@@ -48,7 +48,7 @@ etc.
 What you do with these captured metrics is up to you!
 
 **NOTE**: If any non-`graphql-ruby` gem-related exceptions occur in your application during query document
-parsing and validation, **runtime metrics** for queries (like `query_duration`, `parsing_start_time_offset` etc.) as well as field
+parsing and validation, **runtime metrics** for queries (like `query_duration`, etc.) as well as field
 resolver timings (like `resolver_timings`, `lazy_resolver_timings`) **may not be present** in the extracted `metrics` hash,
 even if you opt to collect them by using `GraphQL::Metrics::Analyzer` and `GraphQL::Metrics::Tracer`.
 
@@ -75,13 +75,9 @@ even if you opt to collect them by using `GraphQL::Metrics::Analyzer` and `Graph
     #   operation_name: "PostDetails",
     #   query_start_time: 1573833076.027327,
     #   query_duration: 2.0207119999686256,
-    #   lexing_start_time_offset: 0.0010339999571442604,
     #   lexing_duration: 0.0008190000080503523,
-    #   parsing_start_time_offset: 0.0010339999571442604,
     #   parsing_duration: 0.0008190000080503523,
-    #   validation_start_time_offset: 0.0030819999519735575,
     #   validation_duration: 0.01704599999357015,
-    #   analysis_start_time_offset: 0.0010339999571442604,
     #   analysis_duration: 0.0008190000080503523,
     #   multiplex_start_time: 0.0008190000080503523,
     # }
@@ -129,12 +125,10 @@ even if you opt to collect them by using `GraphQL::Metrics::Analyzer` and `Graph
     #   deprecated: false,
     #   path: ["post", "id"],
     #   resolver_timings: [
-    #     start_time_offset: 0.011901999998372048,
-    #     duration: 5.999987479299307e-06
+    #     5.999987479299307e-06,
     #   ],
     #   lazy_resolver_timings: [
-    #     start_time_offset: 0.031901999998372048,
-    #     duration: 5.999987479299307e-06
+    #     5.999987479299307e-06,
     #   ],
     # }
     def field_extracted(metrics)

lib/graphql/metrics.rb

@@ -27,13 +27,9 @@ module Metrics
     MULTIPLEX_START_TIME_MONOTONIC = :multiplex_start_time_monotonic
     QUERY_START_TIME = :query_start_time
     QUERY_START_TIME_MONOTONIC = :query_start_time_monotonic
-    LEXING_START_TIME_OFFSET = :lexing_start_time_offset
     LEXING_DURATION = :lexing_duration
-    PARSING_START_TIME_OFFSET = :parsing_start_time_offset
     PARSING_DURATION = :parsing_duration
-    VALIDATION_START_TIME_OFFSET = :validation_start_time_offset
     VALIDATION_DURATION = :validation_duration
-    ANALYSIS_START_TIME_OFFSET = :analysis_start_time_offset
     ANALYSIS_DURATION = :analysis_duration
     INLINE_FIELD_TIMINGS = :inline_field_timings
     LAZY_FIELD_TIMINGS = :lazy_field_timings
@@ -51,40 +47,11 @@ def self.current_time_monotonic
       Process.clock_gettime(Process::CLOCK_MONOTONIC)
     end
 
-    def self.time(offset_time = nil)
+    def self.time
       start_time = current_time_monotonic
       result = yield
       duration = current_time_monotonic - start_time
-      time_since_offset = start_time - offset_time if offset_time
-      TimedResult.new(start_time, duration, time_since_offset, result)
-    end
-
-    class TimedResult
-      # NOTE: `time_since_offset` is used to produce start times timed phases of execution (validation, field
-      # resolution). These start times are relative to the executed operation's start time, which is captured at the
-      # outset of document parsing.
-      #
-      # The times produced are intentionally similar to:
-      # https://github.com/apollographql/apollo-tracing#response-format
-      #
-      # Taking a field resolver start offset example:
-      #
-      # <   start offset   >
-      # |------------------|----------|--------->
-      # OS (t=0)           FS (t=1)   FE (t=2)
-      #
-      # OS = Operation start time
-      # FS = Field resolver start time
-      # FE = Field resolver end time
-      #
-      attr_reader :result, :start_time, :duration, :time_since_offset
-
-      def initialize(start_time, duration, time_since_offset, result)
-        @start_time = start_time
-        @duration = duration
-        @time_since_offset = time_since_offset
-        @result = result
-      end
+      [result, duration]
     end
   end
 end

lib/graphql/metrics/instrumentation.rb

@@ -41,13 +41,9 @@ def after_query(query)
           runtime_query_metrics = {
             query_start_time: ns[GraphQL::Metrics::QUERY_START_TIME],
             query_duration: query_duration,
-            parsing_start_time_offset: ns[GraphQL::Metrics::PARSING_START_TIME_OFFSET],
             parsing_duration: ns[GraphQL::Metrics::PARSING_DURATION],
-            validation_start_time_offset: ns[GraphQL::Metrics::VALIDATION_START_TIME_OFFSET],
             validation_duration: ns[GraphQL::Metrics::VALIDATION_DURATION],
-            lexing_start_time_offset: ns[GraphQL::Metrics::LEXING_START_TIME_OFFSET],
             lexing_duration: ns[GraphQL::Metrics::LEXING_DURATION],
-            analysis_start_time_offset: ns[GraphQL::Metrics::ANALYSIS_START_TIME_OFFSET],
             analysis_duration: ns[GraphQL::Metrics::ANALYSIS_DURATION],
             multiplex_start_time: ns[GraphQL::Metrics::MULTIPLEX_START_TIME],
           }

lib/graphql/metrics/trace.rb

@@ -82,17 +82,13 @@ def skip_tracing?(query_or_multiplex)
       PreContext = Struct.new(
         :multiplex_start_time,
         :multiplex_start_time_monotonic,
-        :parsing_start_time_offset,
         :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
           self[:parsing_duration] = nil
-          self[:lexing_start_time_offset] = nil
           self[:lexing_duration] = nil
         end
       end
@@ -112,61 +108,53 @@ def capture_multiplex_start_time
       end
 
       def capture_lexing_time
-        timed_result = GraphQL::Metrics.time { yield }
+        result, duration = GraphQL::Metrics.time { yield }
 
-        pre_context.lexing_start_time_offset = timed_result.start_time
-        pre_context.lexing_duration = timed_result.duration
+        pre_context.lexing_duration = duration
 
-        timed_result.result
+        result
       end
 
       def capture_parsing_time
-        timed_result = GraphQL::Metrics.time { yield }
+        result, duration = GraphQL::Metrics.time { yield }
 
-        pre_context.parsing_start_time_offset = timed_result.start_time
-        pre_context.parsing_duration = timed_result.duration
+        pre_context.parsing_duration = duration
 
-        timed_result.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 [nil, 0].include?(pre_context.lexing_duration)
-          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 }
+        result, duration = GraphQL::Metrics.time { 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
+        ns[VALIDATION_DURATION] = duration
 
-        timed_result.result
+        result
       end
 
       def capture_analysis_time(context)
         ns = context.namespace(CONTEXT_NAMESPACE)
 
-        timed_result = GraphQL::Metrics.time(ns[MULTIPLEX_START_TIME_MONOTONIC]) { yield }
+        result, duration = GraphQL::Metrics.time { yield }
 
-        ns[ANALYSIS_START_TIME_OFFSET] = timed_result.time_since_offset
-        ns[ANALYSIS_DURATION] = timed_result.duration
+        ns[ANALYSIS_DURATION] = duration
 
-        timed_result.result
+        result
       end
 
       def capture_query_start_time(context)
@@ -179,20 +167,13 @@ def capture_query_start_time(context)
 
       def trace_field(context_key, query)
         ns = query.context.namespace(CONTEXT_NAMESPACE)
-        offset_time = ns[GraphQL::Metrics::QUERY_START_TIME_MONOTONIC]
-        start_time = GraphQL::Metrics.current_time_monotonic
         path = query.context[:current_path]
 
-        result = yield
-
-        duration = GraphQL::Metrics.current_time_monotonic - start_time
-        time_since_offset = start_time - offset_time if offset_time
+        result, duration = GraphQL::Metrics.time { yield }
 
         path_excluding_numeric_indicies = path.select { |p| p.is_a?(String) }
         ns[context_key][path_excluding_numeric_indicies] ||= []
-        ns[context_key][path_excluding_numeric_indicies] << {
-          start_time_offset: time_since_offset, duration: duration
-        }
+        ns[context_key][path_excluding_numeric_indicies] << duration
 
         result
       end