Module: ApolloFederation::Tracing::Tracer

Defined in:
lib/apollo-federation/tracing/tracer.rb

Constant Summary collapse

EXECUTE_MULTIPLEX =

store string constants to avoid creating new strings for each call to .trace

'execute_multiplex'
EXECUTE_QUERY_LAZY = 
'execute_query_lazy'
EXECUTE_FIELD = 
'execute_field'
EXECUTE_FIELD_LAZY = 
'execute_field_lazy'

Class Method Summary collapse

Class Method Details

.attach_trace_to_result(result) ⇒ Object

rubocop:enable Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity



209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 209

def self.attach_trace_to_result(result)
  return result unless result.context[:tracing_enabled]

  trace = result.context.namespace(ApolloFederation::Tracing::KEY)

  result['errors']&.each do |error|
    trace[:node_map].add_error(error)
  end

  proto = ApolloFederation::Tracing::Trace.new(
    start_time: to_proto_timestamp(trace[:start_time]),
    end_time: to_proto_timestamp(trace[:end_time]),
    duration_ns: trace[:end_time_nanos] - trace[:start_time_nanos],
    root: trace[:node_map].root,
  )

  result[:extensions] ||= {}
  result[:extensions][ApolloFederation::Tracing::KEY] =
    Base64.encode64(proto.class.encode(proto))

  if result.context[:debug_tracing]
    result[:extensions][ApolloFederation::Tracing::DEBUG_KEY] = proto.to_h
  end

  result
end

.execute_field(data, &block) ⇒ Object

Step 2:

  • Record start and end times for the field resolver.

  • Rescue errors so the method doesn’t exit early.

  • Create a trace “node” and attach field details.

  • Propagate the error (if necessary) so it ends up in the top-level errors array.

The values in ‘data` are different depending on the executor runtime. graphql-ruby.org/api-doc/1.9.3/GraphQL/Tracing

Nodes are added the NodeMap stored in the trace hash.

Errors are added to nodes in ‘ApolloFederation::Tracing.attach_trace_to_result` because we don’t have the error ‘location` here. rubocop:disable Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity



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
156
157
158
159
160
161
162
163
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 122

def self.execute_field(data, &block)
  context = data.fetch(:context, nil) || data.fetch(:query).context
  return block.call unless context && context[:tracing_enabled]

  start_time_nanos = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond)

  begin
    result = block.call
  rescue StandardError => e
    error = e
  end

  end_time_nanos = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond)

  # legacy runtime
  if data.include?(:context)
    path = context.path
    field_name = context.field.graphql_name
    field_type = context.field.type.to_s
    parent_type = context.parent_type.graphql_name
  else # interpreter runtime
    path = data.fetch(:path)
    field = data.fetch(:field)
    field_name = field.graphql_name
    field_type = field.type.to_type_signature
    parent_type = data.fetch(:owner).graphql_name
  end

  trace = context.namespace(ApolloFederation::Tracing::KEY)
  node = trace[:node_map].add(path)

  # original_field_name is set only for aliased fields
  node.original_field_name = field_name if field_name != path.last
  node.type = field_type
  node.parent_type = parent_type
  node.start_time = start_time_nanos - trace[:start_time_nanos]
  node.end_time = end_time_nanos - trace[:start_time_nanos]

  raise error if error

  result
end

.execute_field_lazy(data, &block) ⇒ Object

Optional Step 3: Overwrite the end times on the trace node if the resolver was lazy.



167
168
169
170
171
172
173
174
175
176
177
178
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
204
205
206
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 167

def self.execute_field_lazy(data, &block)
  context = data.fetch(:context, nil) || data.fetch(:query).context
  return block.call unless context && context[:tracing_enabled]

  begin
    result = block.call
  rescue StandardError => e
    error = e
  end

  end_time_nanos = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond)

  # legacy runtime
  if data.include?(:context)
    path = context.path
    field = context.field
  else # interpreter runtime
    path = data.fetch(:path)
    field = data.fetch(:field)
  end

  trace = context.namespace(ApolloFederation::Tracing::KEY)

  # When a field is resolved with an array of lazy values, the interpreter fires an
  # `execute_field` for the resolution of the field and then a `execute_field_lazy` event for
  # each lazy value in the array. Since the path here will contain an index (indicating which
  # lazy value we're executing: e.g. ['arrayOfLazies', 0]), we won't have a node for the path.
  # We only care about the end of the parent field (e.g. ['arrayOfLazies']), so we get the
  # node for that path. What ends up happening is we update the end_time for the parent node
  # for each of the lazy values. The last one that's executed becomes the final end time.
  if field.type.list? && path.last.is_a?(Integer)
    path = path[0...-1]
  end
  node = trace[:node_map].node_for_path(path)
  node.end_time = end_time_nanos - trace[:start_time_nanos]

  raise error if error

  result
end

.execute_multiplex(data, &block) ⇒ Object 



58
59
60
61
62
63
64
65
66
67
68
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 58

def self.execute_multiplex(data, &block)
  # Step 1:
  # Create a trace hash on each query's context and record start times.
  data.fetch(:multiplex).queries.each { |query| start_trace(query) }

  results = block.call

  # Step 5
  # Attach the trace to the 'extensions' key of each result
  results.map { |result| attach_trace_to_result(result) }
end

.execute_query_lazy(data, &block) ⇒ Object

Step 4: Record end times and merge them into the trace hash.



82
83
84
85
86
87
88
89
90
91
92
93
94
95
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 82

def self.execute_query_lazy(data, &block)
  result = block.call

  query = data.fetch(:query)
  multiplex = data.fetch(:multiplex)

  if query
    record_trace_end_time(query)
  elsif multiplex
    multiplex.queries.each { |q| record_trace_end_time(q) }
  end

  result
end

.record_trace_end_time(query) ⇒ Object 



97
98
99
100
101
102
103
104
105
106
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 97

def self.record_trace_end_time(query)
  return unless query.context && query.context[:tracing_enabled]

  trace = query.context.namespace(ApolloFederation::Tracing::KEY)

  trace.merge!(
    end_time: Time.now.utc,
    end_time_nanos: Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond),
  )
end

.start_trace(query) ⇒ Object 



70
71
72
73
74
75
76
77
78
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 70

def self.start_trace(query)
  return unless query.context && query.context[:tracing_enabled]

  query.context.namespace(ApolloFederation::Tracing::KEY).merge!(
    start_time: Time.now.utc,
    start_time_nanos: Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond),
    node_map: NodeMap.new,
  )
end

.to_proto_timestamp(time) ⇒ Object 



236
237
238
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 236

def self.to_proto_timestamp(time)
  Google::Protobuf::Timestamp.new(seconds: time.to_i, nanos: time.nsec)
end

.trace(key, data, &block) ⇒ Object 



43
44
45
46
47
48
49
50
51
52
53
54
55
56
 
# File 'lib/apollo-federation/tracing/tracer.rb', line 43

def self.trace(key, data, &block)
  case key
  when EXECUTE_MULTIPLEX
    execute_multiplex(data, &block)
  when EXECUTE_QUERY_LAZY
    execute_query_lazy(data, &block)
  when EXECUTE_FIELD
    execute_field(data, &block)
  when EXECUTE_FIELD_LAZY
    execute_field_lazy(data, &block)
  else
    yield
  end
end