diff --git a/.rubocop.yml b/.rubocop.yml index 626427e895..3b4bbe316e 100644 --- a/.rubocop.yml +++ b/.rubocop.yml @@ -48,7 +48,7 @@ Development/NoFocusCop: Development/TraceMethodsCop: Include: - "lib/graphql/tracing/perfetto_trace.rb" - - "lib/graphql/tracing/new_relic_trace.rb" + - "lib/graphql/tracing/notifications_trace.rb" # def ... # end diff --git a/cop/development/trace_methods_cop.rb b/cop/development/trace_methods_cop.rb index 1d99f69b48..ec843a99c5 100644 --- a/cop/development/trace_methods_cop.rb +++ b/cop/development/trace_methods_cop.rb @@ -16,8 +16,6 @@ class TraceMethodsCop < RuboCop::Cop::Base :begin_dataloader, :begin_dataloader_source, :begin_execute_field, - :begin_execute_multiplex, - :begin_parse, :begin_resolve_type, :begin_validate, :dataloader_fiber_exit, @@ -30,8 +28,6 @@ class TraceMethodsCop < RuboCop::Cop::Base :end_dataloader, :end_dataloader_source, :end_execute_field, - :end_execute_multiplex, - :end_parse, :end_resolve_type, :end_validate, :execute_field, @@ -73,6 +69,7 @@ def on_module(node) # Not really necessary for making a good trace: :lex, :analyze_query, :execute_query, :execute_query_lazy, # Only useful for isolated event tracking: + :begin_dataloader, :end_dataloader, :dataloader_fiber_exit, :dataloader_spawn_execution_fiber, :dataloader_spawn_source_fiber ] missing_defs.each do |missing_def| @@ -80,6 +77,12 @@ def on_module(node) redundant_defs << missing_def redundant_defs << :"#{missing_def}_lazy" end + missing_name = missing_def.to_s + if missing_name.start_with?("begin") && all_defs.include?(:"#{missing_name.sub("begin_", "")}") + redundant_defs << missing_def + elsif missing_name.start_with?("end") && all_defs.include?(:"#{missing_name.sub("end_", "")}") + redundant_defs << missing_def + end end missing_defs -= redundant_defs diff --git a/lib/graphql/execution/interpreter.rb b/lib/graphql/execution/interpreter.rb index f2a4a6481d..4b5ca7d8de 100644 --- a/lib/graphql/execution/interpreter.rb +++ b/lib/graphql/execution/interpreter.rb @@ -37,7 +37,6 @@ def run_all(schema, query_options, context: {}, max_complexity: schema.max_compl multiplex = Execution::Multiplex.new(schema: schema, queries: queries, context: context, max_complexity: max_complexity) Fiber[:__graphql_current_multiplex] = multiplex trace = multiplex.current_trace - trace.begin_execute_multiplex(multiplex) trace.execute_multiplex(multiplex: multiplex) do schema = multiplex.schema queries = multiplex.queries @@ -154,8 +153,6 @@ def run_all(schema, query_options, context: {}, max_complexity: schema.max_compl } end end - ensure - trace&.end_execute_multiplex(multiplex) end end diff --git a/lib/graphql/query.rb b/lib/graphql/query.rb index a6503964f3..e9df98649a 100644 --- a/lib/graphql/query.rb +++ b/lib/graphql/query.rb @@ -441,7 +441,6 @@ def prepare_ast @warden ||= @schema.warden_class.new(schema: @schema, context: @context) parse_error = nil @document ||= begin - current_trace.begin_parse(query_string) if query_string GraphQL.parse(query_string, trace: self.current_trace, max_tokens: @schema.max_query_string_tokens) end @@ -449,8 +448,6 @@ def prepare_ast parse_error = err @schema.parse_error(err, @context) nil - ensure - current_trace.end_parse(query_string) end @fragments = {} diff --git a/lib/graphql/tracing.rb b/lib/graphql/tracing.rb index 1c117b9c9d..56f06e9f6c 100644 --- a/lib/graphql/tracing.rb +++ b/lib/graphql/tracing.rb @@ -25,6 +25,7 @@ module Tracing autoload :AppOpticsTrace, "graphql/tracing/appoptics_trace" autoload :AppsignalTrace, "graphql/tracing/appsignal_trace" autoload :DataDogTrace, "graphql/tracing/data_dog_trace" + autoload :MonitorTrace, "graphql/tracing/monitor_trace" autoload :NewRelicTrace, "graphql/tracing/new_relic_trace" autoload :NotificationsTrace, "graphql/tracing/notifications_trace" autoload :SentryTrace, "graphql/tracing/sentry_trace" diff --git a/lib/graphql/tracing/active_support_notifications_trace.rb b/lib/graphql/tracing/active_support_notifications_trace.rb index ef0d2752a1..b5ca85ff60 100644 --- a/lib/graphql/tracing/active_support_notifications_trace.rb +++ b/lib/graphql/tracing/active_support_notifications_trace.rb @@ -10,6 +10,13 @@ module Tracing # class MySchema < GraphQL::Schema # trace_with(GraphQL::Tracing::ActiveSupportNotificationsTrace) # end + # + # @example Subscribing to GraphQL events with ActiveSupport::Notifications + # ActiveSupport::Notifications.subscribe(/graphql/) do |event| + # pp event.name + # pp event.payload + # end + # module ActiveSupportNotificationsTrace include NotificationsTrace def initialize(engine: ActiveSupport::Notifications, **rest) diff --git a/lib/graphql/tracing/monitor_trace.rb b/lib/graphql/tracing/monitor_trace.rb new file mode 100644 index 0000000000..067764ff14 --- /dev/null +++ b/lib/graphql/tracing/monitor_trace.rb @@ -0,0 +1,228 @@ +# frozen_string_literal: true + +module GraphQL + module Tracing + # This module is the basis for Ruby-level integration with third-party monitoring platforms. + # Platform-specific traces include this module and implement an adapter. + # + # @see ActiveSupportNotificationsTrace Integration via ActiveSupport::Notifications, an alternative approach. + module MonitorTrace + class Monitor + def initialize(set_transaction_name:) + @set_transaction_name = set_transaction_name + @platform_field_key_cache = Hash.new { |h, k| h[k] = platform_field_key(k) }.compare_by_identity + @platform_authorized_key_cache = Hash.new { |h, k| h[k] = platform_authorized_key(k) }.compare_by_identity + @platform_resolve_type_key_cache = Hash.new { |h, k| h[k] = platform_resolve_type_key(k) }.compare_by_identity + @platform_source_class_key_cache = Hash.new { |h, source_cls| h[source_cls] = platform_source_class_key(source_cls) }.compare_by_identity + end + + def instrument(keyword, object, &block) + raise "Implement #{self.class}#instrument to measure the block" + end + + def start_event(keyword, object) + ev = self.class::Event.new(self, keyword, object) + ev.start + ev + end + + # Get the transaction name based on the operation type and name if possible, or fall back to a user provided + # one. Useful for anonymous queries. + def transaction_name(query) + selected_op = query.selected_operation + txn_name = if selected_op + op_type = selected_op.operation_type + op_name = selected_op.name || fallback_transaction_name(query.context) || "anonymous" + "#{op_type}.#{op_name}" + else + "query.anonymous" + end + "GraphQL/#{txn_name}" + end + + def fallback_transaction_name(context) + context[:tracing_fallback_transaction_name] + end + + def name_for(keyword, object) + case keyword + when :execute_field + @platform_field_key_cache[object] + when :authorized + @platform_authorized_key_cache[object] + when :resolve_type + @platform_resolve_type_key_cache[object] + when :dataloader_source + @platform_source_class_key_cache[object.class] + when :parse then self.class::PARSE_NAME + when :lex then self.class::LEX_NAME + when :execute then self.class::EXECUTE_NAME + when :analyze then self.class::ANALYZE_NAME + when :validate then self.class::VALIDATE_NAME + else + raise "No name for #{keyword.inspect}" + end + end + + class Event + def initialize(engine, keyword, object) + @engine = engine + @keyword = keyword + @object = object + end + + attr_reader :keyword, :object + + def start + raise "Implement #{self.class}#start to begin a new event (#{inspect})" + end + + def finish + raise "Implement #{self.class}#finish to end this event (#{inspect})" + end + end + end + + def self.create_module(monitor_name) + if !monitor_name.match?(/[a-z]+/) + raise ArgumentError, "monitor name must be [a-z]+, not: #{monitor_name.inspect}" + end + + trace_module = Module.new + code = MODULE_TEMPLATE % { + monitor: monitor_name, + monitor_class: monitor_name.capitalize + "Monitor", + } + trace_module.module_eval(code, __FILE__, __LINE__ + 5) + trace_module + end + + MODULE_TEMPLATE = <<~RUBY + # @param set_transaction_name [Boolean] If `true`, use the GraphQL operation name as the request name on the monitoring platform + # @param trace_scalars [Boolean] If `true`, leaf fields will be traced too (Scalars _and_ Enums) + # @param trace_authorized [Boolean] If `false`, skip tracing `authorized?` calls + # @param trace_resolve_type [Boolean] If `false`, skip tracing `resolve_type?` calls + def initialize(set_transaction_name: false, trace_scalars: false, trace_authorized: true, trace_resolve_type: true, **rest) + @trace_scalars = trace_scalars + @trace_authorized = trace_authorized + @trace_resolve_type = trace_resolve_type + @set_transaction_name = set_transaction_name + @%{monitor} = %{monitor_class}.new(set_transaction_name: @set_transaction_name) + super + end + + def parse(query_string:) + @%{monitor}.instrument(:parse, query_string) do + super + end + end + + def lex(query_string:) + @%{monitor}.instrument(:lex, query_string) do + super + end + end + + def validate(query:, validate:) + @%{monitor}.instrument(:validate, query) do + super + end + end + + def begin_analyze_multiplex(multiplex, analyzers) + begin_%{monitor}_event(:analyze, nil) + super + end + + def end_analyze_multiplex(multiplex, analyzers) + finish_%{monitor}_event + super + end + + def execute_multiplex(multiplex:) + @%{monitor}.instrument(:execute, multiplex) do + super + end + end + + def begin_execute_field(field, object, arguments, query) + return_type = field.type.unwrap + trace_field = if return_type.kind.scalar? || return_type.kind.enum? + (field.trace.nil? && @trace_scalars) || field.trace + else + true + end + + if trace_field + begin_%{monitor}_event(:execute_field, field) + end + super + end + + def end_execute_field(field, object, arguments, query, result) + finish_%{monitor}_event + super + end + + def dataloader_fiber_yield(source) + Fiber[PREVIOUS_EV_KEY] = finish_%{monitor}_event + super + end + + def dataloader_fiber_resume(source) + prev_ev = Fiber[PREVIOUS_EV_KEY] + begin_%{monitor}_event(prev_ev.keyword, prev_ev.object) + super + end + + def begin_authorized(type, object, context) + @trace_authorized && begin_%{monitor}_event(:authorized, type) + super + end + + def end_authorized(type, object, context, result) + finish_%{monitor}_event + super + end + + def begin_resolve_type(type, value, context) + @trace_resolve_type && begin_%{monitor}_event(:resolve_type, type) + super + end + + def end_resolve_type(type, value, context, resolved_type) + finish_%{monitor}_event + super + end + + def begin_dataloader_source(source) + begin_%{monitor}_event(:dataloader_source, source) + super + end + + def end_dataloader_source(source) + finish_%{monitor}_event + super + end + + CURRENT_EV_KEY = :__graphql_%{monitor}_trace_event + PREVIOUS_EV_KEY = :__graphql_%{monitor}_trace_previous_event + + private + + def begin_%{monitor}_event(keyword, object) + Fiber[CURRENT_EV_KEY] = @%{monitor}.start_event(keyword, object) + end + + def finish_%{monitor}_event + if ev = Fiber[CURRENT_EV_KEY] + ev.finish + # Use `false` to prevent grabbing an event from a parent fiber + Fiber[CURRENT_EV_KEY] = false + ev + end + end + RUBY + end + end +end diff --git a/lib/graphql/tracing/new_relic_trace.rb b/lib/graphql/tracing/new_relic_trace.rb index 2e346fb501..4eb3cb797a 100644 --- a/lib/graphql/tracing/new_relic_trace.rb +++ b/lib/graphql/tracing/new_relic_trace.rb @@ -1,6 +1,6 @@ # frozen_string_literal: true -require "graphql/tracing/platform_trace" +require "graphql/tracing/monitor_trace" module GraphQL module Tracing @@ -16,170 +16,52 @@ module Tracing # # @example Installing without trace events for `authorized?` or `resolve_type` calls # trace_with GraphQL::Tracing::NewRelicTrace, trace_authorized: false, trace_resolve_type: false + NewRelicTrace = MonitorTrace.create_module("newrelic") module NewRelicTrace - # @param set_transaction_name [Boolean] If true, the GraphQL operation name will be used as the transaction name. - # This is not advised if you run more than one query per HTTP request, for example, with `graphql-client` or multiplexing. - # It can also be specified per-query with `context[:set_new_relic_transaction_name]`. - # @param trace_authorized [Boolean] If `false`, skip tracing `authorized?` calls - # @param trace_resolve_type [Boolean] If `false`, skip tracing `resolve_type?` calls - def initialize(set_transaction_name: false, trace_authorized: true, trace_resolve_type: true, **_rest) - @set_transaction_name = set_transaction_name - @trace_authorized = trace_authorized - @trace_resolve_type = trace_resolve_type - @nr_field_names = Hash.new do |h, field| - h[field] = "GraphQL/#{field.owner.graphql_name}/#{field.graphql_name}" - end.compare_by_identity - - @nr_authorized_names = Hash.new do |h, type| - h[type] = "GraphQL/Authorized/#{type.graphql_name}" - end.compare_by_identity - - @nr_resolve_type_names = Hash.new do |h, type| - h[type] = "GraphQL/ResolveType/#{type.graphql_name}" - end.compare_by_identity - - @nr_source_names = Hash.new do |h, source_inst| - h[source_inst] = "GraphQL/Source/#{source_inst.class.name}" - end.compare_by_identity - - @nr_parse = @nr_validate = @nr_analyze = @nr_execute = nil - super - end - - def begin_parse(query_str) - @nr_parse = NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: "GraphQL/parse", category: :web) - super - end - - def end_parse(query_str) - @nr_parse.finish - super - end - - def begin_validate(query, validate) - @nr_validate = NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: "GraphQL/validate", category: :web) - super - end - - def end_validate(query, validate, validation_errors) - @nr_validate.finish - super - end - - def begin_analyze_multiplex(multiplex, analyzers) - @nr_analyze = NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: "GraphQL/analyze", category: :web) - super - end - - def end_analyze_multiplex(multiplex, analyzers) - @nr_analyze.finish - super - end - - def begin_execute_multiplex(multiplex) - query = multiplex.queries.first - set_this_txn_name = query.context[:set_new_relic_transaction_name] - if set_this_txn_name || (set_this_txn_name.nil? && @set_transaction_name) - NewRelic::Agent.set_transaction_name(transaction_name(query)) + class NewrelicMonitor < MonitorTrace::Monitor + PARSE_NAME = "GraphQL/parse" + LEX_NAME = "GraphQL/lex" + VALIDATE_NAME = "GraphQL/validate" + EXECUTE_NAME = "GraphQL/execute" + ANALYZE_NAME = "GraphQL/analyze" + + def instrument(keyword, payload, &block) + if keyword == :execute && payload.queries.size == 1 + query = payload.queries.first + set_this_txn_name = query.context[:set_new_relic_transaction_name] + if set_this_txn_name || (set_this_txn_name.nil? && @set_transaction_name) + NewRelic::Agent.set_transaction_name(transaction_name(query)) + end + end + ::NewRelic::Agent::MethodTracerHelpers.trace_execution_scoped(name_for(keyword, payload), &block) end - @nr_execute = NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: "GraphQL/execute", category: :web) - super - end - - def end_execute_multiplex(multiplex) - @nr_execute.finish - super - end - - def begin_execute_field(field, object, arguments, query) - nr_segment_stack << NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: @nr_field_names[field], category: :web) - super - end - def end_execute_field(field, objects, arguments, query, result) - nr_segment_stack.pop.finish - super - end - - def begin_authorized(type, obj, ctx) - if @trace_authorized - nr_segment_stack << NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: @nr_authorized_names[type], category: :web) + def platform_source_class_key(source_class) + "GraphQL/Source/#{source_class.name}" end - super - end - def end_authorized(type, obj, ctx, is_authed) - if @trace_authorized - nr_segment_stack.pop.finish + def platform_field_key(field) + "GraphQL/#{field.owner.graphql_name}/#{field.graphql_name}" end - super - end - def begin_resolve_type(type, value, context) - if @trace_resolve_type - nr_segment_stack << NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: @nr_resolve_type_names[type], category: :web) + def platform_authorized_key(type) + "GraphQL/Authorized/#{type.graphql_name}" end - super - end - def end_resolve_type(type, value, context, resolved_type) - if @trace_resolve_type - nr_segment_stack.pop.finish + def platform_resolve_type_key(type) + "GraphQL/ResolveType/#{type.graphql_name}" end - super - end - - def begin_dataloader(dl) - super - end - - def end_dataloader(dl) - super - end - - def begin_dataloader_source(source) - nr_segment_stack << NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: @nr_source_names[source], category: :web) - super - end - - def end_dataloader_source(source) - nr_segment_stack.pop.finish - super - end - def dataloader_fiber_yield(source) - current_segment = nr_segment_stack.last - current_segment.finish - super - end - - def dataloader_fiber_resume(source) - prev_segment = nr_segment_stack.pop - seg_partial_name = prev_segment.name.sub(/^.*(GraphQL.*)$/, '\1') - nr_segment_stack << NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: seg_partial_name, category: :web) - super - end + class Event < MonitorTrace::Monitor::Event + def start + name = @engine.name_for(keyword, object) + @nr_ev = NewRelic::Agent::Tracer.start_transaction_or_segment(partial_name: name, category: :web) + end - private - - def nr_segment_stack - Fiber[:graphql_nr_segment_stack] ||= [] - end - - def transaction_name(query) - selected_op = query.selected_operation - txn_name = if selected_op - op_type = selected_op.operation_type - op_name = selected_op.name || fallback_transaction_name(query.context) || "anonymous" - "#{op_type}.#{op_name}" - else - "query.anonymous" + def finish + @nr_ev.finish + end end - "GraphQL/#{txn_name}" - end - - def fallback_transaction_name(context) - context[:tracing_fallback_transaction_name] end end end diff --git a/lib/graphql/tracing/notifications_trace.rb b/lib/graphql/tracing/notifications_trace.rb index 406068aa53..520c3adb50 100644 --- a/lib/graphql/tracing/notifications_trace.rb +++ b/lib/graphql/tracing/notifications_trace.rb @@ -1,45 +1,193 @@ # frozen_string_literal: true -require "graphql/tracing/platform_trace" - module GraphQL module Tracing - # This implementation forwards events to a notification handler (i.e. - # ActiveSupport::Notifications or Dry::Monitor::Notifications) - # with a `graphql` suffix. + # This implementation forwards events to a notification handler + # (i.e. ActiveSupport::Notifications or Dry::Monitor::Notifications) with a `graphql` suffix. + # + # @see ActiveSupportNotificationsTrace ActiveSupport::Notifications integration module NotificationsTrace - # Initialize a new NotificationsTracing instance - # - # @param engine [#instrument(key, metadata, block)] The notifications engine to use - def initialize(engine:, **rest) - @notifications_engine = engine - super - end - - { - "lex" => "lex.graphql", - "parse" => "parse.graphql", - "validate" => "validate.graphql", - "analyze_multiplex" => "analyze_multiplex.graphql", - "analyze_query" => "analyze_query.graphql", - "execute_multiplex" => "execute_multiplex.graphql", - "execute_query" => "execute_query.graphql", - "execute_query_lazy" => "execute_query_lazy.graphql", - "execute_field" => "execute_field.graphql", - "execute_field_lazy" => "execute_field_lazy.graphql", - "authorized" => "authorized.graphql", - "authorized_lazy" => "authorized_lazy.graphql", - "resolve_type" => "resolve_type.graphql", - "resolve_type_lazy" => "resolve_type.graphql", - }.each do |trace_method, platform_key| - module_eval <<-RUBY, __FILE__, __LINE__ - def #{trace_method}(**metadata, &block) - @notifications_engine.instrument("#{platform_key}", metadata) { super(**metadata, &block) } + # @api private + class Adapter + def instrument(keyword, payload, &block) + raise "Implement #{self.class}#instrument to measure the block" + end + + def start_event(keyword, payload) + ev = self.class::Event.new(keyword, payload) + ev.start + ev + end + + class Event + def initialize(name, payload) + @name = name + @payload = payload + end + + attr_reader :name, :payload + + def start + raise "Implement #{self.class}#start to begin a new event (#{inspect})" + end + + def finish + raise "Implement #{self.class}#finish to end this event (#{inspect})" + end + end + end + + # @api private + class DryMonitorAdapter < Adapter + def instrument(...) + Dry::Monitor.instrument(...) + end + + class Event < Adapter::Event + def start + Dry::Monitor.start(@name, @payload) + end + + def finish + Dry::Monitor.stop(@name, @payload) + end + end + end + + # @api private + class ActiveSupportNotificationsAdapter < Adapter + def instrument(...) + ActiveSupport::Notifications.instrument(...) + end + + class Event < Adapter::Event + def start + @asn_event = ActiveSupport::Notifications.instrumenter.new_event(@name, @payload) + @asn_event.start! end - RUBY + + def finish + @asn_event.finish! + ActiveSupport::Notifications.publish_event(@asn_event) + end + end + end + + # @param engine [Class] The notifications engine to use, eg `Dry::Monitor` or `ActiveSupport::Notifications` + def initialize(engine:, **rest) + adapter = if defined?(Dry::Monitor) && engine == Dry::Monitor + DryMonitoringAdapter + elsif defined?(ActiveSupport::Notifications) && engine == ActiveSupport::Notifications + ActiveSupportNotificationsAdapter + else + engine + end + @notifications = adapter.new + super + end + + def parse(**payload) + @notifications.instrument("parse.graphql", payload) do + super + end + end + + def lex(**payload) + @notifications.instrument("lex.graphql", payload) do + super + end + end + + def validate(**payload) + @notifications.instrument("validate.graphql", payload) do + super + end + end + + def begin_analyze_multiplex(multiplex, analyzers) + begin_notifications_event("analyze.graphql", {multiplex: multiplex, analyzers: analyzers}) + super + end + + def end_analyze_multiplex(_multiplex, _analyzers) + finish_notifications_event + super end - include PlatformTrace + def execute_multiplex(**payload) + @notifications.instrument("execute.graphql", payload) do + super + end + end + + def begin_execute_field(field, object, arguments, query) + begin_notifications_event("execute_field.graphql", {field: field, object: object, arguments: arguments, query: query}) + super + end + + def end_execute_field(_field, _object, _arguments, _query, _result) + finish_notifications_event + super + end + + def dataloader_fiber_yield(source) + Fiber[PREVIOUS_EV_KEY] = finish_notifications_event + super + end + + def dataloader_fiber_resume(source) + prev_ev = Fiber[PREVIOUS_EV_KEY] + begin_notifications_event(prev_ev.name, prev_ev.payload) + super + end + + def begin_authorized(type, object, context) + begin_notifications_event("authorized.graphql", {type: type, object: object, context: context}) + super + end + + def end_authorized(type, object, context, result) + finish_notifications_event + super + end + + def begin_resolve_type(type, object, context) + begin_notifications_event("resolve_type.graphql", {type: type, object: object, context: context}) + super + end + + def end_resolve_type(type, object, context, resolved_type) + finish_notifications_event + super + end + + def begin_dataloader_source(source) + begin_notifications_event("dataloader_source.graphql", { source: source }) + super + end + + def end_dataloader_source(source) + finish_notifications_event + super + end + + CURRENT_EV_KEY = :__notifications_graphql_trace_event + PREVIOUS_EV_KEY = :__notifications_graphql_trace_previous_event + + private + + def begin_notifications_event(name, payload) + Fiber[CURRENT_EV_KEY] = @notifications.start_event(name, payload) + end + + def finish_notifications_event + if ev = Fiber[CURRENT_EV_KEY] + ev.finish + # Use `false` to prevent grabbing an event from a parent fiber + Fiber[CURRENT_EV_KEY] = false + ev + end + end end end end diff --git a/lib/graphql/tracing/perfetto_trace.rb b/lib/graphql/tracing/perfetto_trace.rb index 3f7082ecd0..bcaf8f4e9e 100644 --- a/lib/graphql/tracing/perfetto_trace.rb +++ b/lib/graphql/tracing/perfetto_trace.rb @@ -174,33 +174,33 @@ def initialize(active_support_notifications_pattern: nil, save_profile: false, * end end - def begin_execute_multiplex(m) - @operation_name = m.queries.map { |q| q.selected_operation_name || "anonymous" }.join(",") + def execute_multiplex(multiplex:) + @operation_name = multiplex.queries.map { |q| q.selected_operation_name || "anonymous" }.join(",") @begin_time = Time.now @packets << trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, name: "Multiplex", debug_annotations: [ - payload_to_debug("query_string", m.queries.map(&:sanitized_query_string).join("\n\n")) + payload_to_debug("query_string", multiplex.queries.map(&:sanitized_query_string).join("\n\n")) ] ) - super - end + result = super - def end_execute_multiplex(m) @packets << trace_packet( type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, ) + + result + ensure unsubscribe_from_active_support_notifications if @save_profile begin_ts = (@begin_time.to_f * 1000).round end_ts = (Time.now.to_f * 1000).round duration_ms = end_ts - begin_ts - m.schema.detailed_trace.save_trace(@operation_name, duration_ms, begin_ts, Trace.encode(Trace.new(packet: @packets))) + multiplex.schema.detailed_trace.save_trace(@operation_name, duration_ms, begin_ts, Trace.encode(Trace.new(packet: @packets))) end - super end def begin_execute_field(field, object, arguments, query) @@ -261,7 +261,7 @@ def end_analyze_multiplex(m, analyzers) super end - def begin_parse(str) + def parse(query_string:) @packets << trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, @@ -269,17 +269,14 @@ def begin_parse(str) extra_counter_values: [count_allocations], name: "Parse" ) - super - end - - def end_parse(str) + result = super @packets << trace_packet( type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, extra_counter_track_uuids: [@objects_counter_id], extra_counter_values: [count_allocations], ) - super + result end def begin_validate(query, validate) diff --git a/lib/graphql/tracing/sentry_trace.rb b/lib/graphql/tracing/sentry_trace.rb index 1894c486ad..8d93727d8f 100644 --- a/lib/graphql/tracing/sentry_trace.rb +++ b/lib/graphql/tracing/sentry_trace.rb @@ -1,117 +1,99 @@ # frozen_string_literal: true -require "graphql/tracing/platform_trace" +require "graphql/tracing/monitor_trace" module GraphQL module Tracing # A tracer for reporting GraphQL-Ruby times to Sentry. + # # @example Installing the tracer # class MySchema < GraphQL::Schema # trace_with GraphQL::Tracing::SentryTrace # end + # @see MonitorTrace Configuration Options in the parent module + SentryTrace = MonitorTrace.create_module("sentry") module SentryTrace - include PlatformTrace - - # @param set_transaction_name [Boolean] If true, the GraphQL operation name will be used as the transaction name. - # This is not advised if you run more than one query per HTTP request, for example, with `graphql-client` or multiplexing. - # It can also be specified per-query with `context[:set_sentry_transaction_name]`. - def initialize(set_transaction_name: false, **_rest) - @set_transaction_name = set_transaction_name - super - end - - def execute_query(**data) - set_this_txn_name = data[:query].context[:set_sentry_transaction_name] - if set_this_txn_name == true || (set_this_txn_name.nil? && @set_transaction_name) - Sentry.configure_scope do |scope| - scope.set_transaction_name(transaction_name(data[:query])) + class SentryMonitor < MonitorTrace::Monitor + def instrument(keyword, object) + return yield unless Sentry.initialized? + + platform_key = name_for(keyword, object) + + Sentry.with_child_span(op: platform_key, start_timestamp: Sentry.utc_now.to_f) do |span| + result = yield + return result unless span + + span.finish + if keyword == :execute + queries = object.queries + operation_names = queries.map{|q| operation_name(q) } + span.set_description(operation_names.join(", ")) + + if queries.size == 1 + query = queries.first + set_this_txn_name = query.context[:set_sentry_transaction_name] + if set_this_txn_name == true || (set_this_txn_name.nil? && @set_transaction_name) + Sentry.configure_scope do |scope| + scope.set_transaction_name(transaction_name(query)) + end + end + span.set_data('graphql.document', query.query_string) + if query.selected_operation_name + span.set_data('graphql.operation.name', query.selected_operation_name) + end + span.set_data('graphql.operation.type', query.selected_operation.operation_type) + end + end + + result end end - instrument_sentry_execution("graphql.execute", "execute_query", data) { super } - end - - { - "lex" => "graphql.lex", - "parse" => "graphql.parse", - "validate" => "graphql.validate", - "analyze_query" => "graphql.analyze", - "analyze_multiplex" => "graphql.analyze_multiplex", - "execute_multiplex" => "graphql.execute_multiplex", - "execute_query_lazy" => "graphql.execute" - }.each do |trace_method, platform_key| - module_eval <<-RUBY, __FILE__, __LINE__ - def #{trace_method}(**data) - instrument_sentry_execution("#{platform_key}", "#{trace_method}", data) { super } - end - RUBY - end - - def platform_execute_field(platform_key, &block) - instrument_sentry_execution(platform_key, "execute_field", &block) - end - - def platform_execute_field_lazy(platform_key, &block) - instrument_sentry_execution(platform_key, "execute_field_lazy", &block) - end - - def platform_authorized(platform_key, &block) - instrument_sentry_execution(platform_key, "authorized", &block) - end - - def platform_authorized_lazy(platform_key, &block) - instrument_sentry_execution(platform_key, "authorized_lazy", &block) - end - - def platform_resolve_type(platform_key, &block) - instrument_sentry_execution(platform_key, "resolve_type", &block) - end - def platform_resolve_type_lazy(platform_key, &block) - instrument_sentry_execution(platform_key, "resolve_type_lazy", &block) - end + PARSE_NAME = "graphql.parse" + LEX_NAME = "graphql.lex" + VALIDATE_NAME = "graphql.validate" + EXECUTE_NAME = "graphql.execute" + ANALYZE_NAME = "graphql.analyze" - def platform_field_key(field) - "graphql.field.#{field.path}" - end + private - def platform_authorized_key(type) - "graphql.authorized.#{type.graphql_name}" - end + def operation_name(query) + selected_op = query.selected_operation + if selected_op + [selected_op.operation_type, selected_op.name].compact.join(' ') + else + 'GraphQL Operation' + end + end - def platform_resolve_type_key(type) - "graphql.resolve_type.#{type.graphql_name}" - end + def platform_field_key(field) + "graphql.field.#{field.path}" + end - private + def platform_authorized_key(type) + "graphql.authorized.#{type.graphql_name}" + end - def instrument_sentry_execution(platform_key, trace_method, data=nil, &block) - return yield unless Sentry.initialized? + def platform_resolve_type_key(type) + "graphql.resolve_type.#{type.graphql_name}" + end - Sentry.with_child_span(op: platform_key, start_timestamp: Sentry.utc_now.to_f) do |span| - result = yield - return result unless span + def platform_source_class_key(source_class) + "graphql.source.#{source_class.name.gsub("::", ".")}" + end - span.finish - if trace_method == "execute_multiplex" && data.key?(:multiplex) - operation_names = data[:multiplex].queries.map{|q| operation_name(q) } - span.set_description(operation_names.join(", ")) - elsif trace_method == "execute_query" && data.key?(:query) - span.set_description(operation_name(data[:query])) - span.set_data('graphql.document', data[:query].query_string) - span.set_data('graphql.operation.name', data[:query].selected_operation_name) if data[:query].selected_operation_name - span.set_data('graphql.operation.type', data[:query].selected_operation.operation_type) + class Event < MonitorTrace::Monitor::Event + def start + if Sentry.initialized? + @span = Sentry.get_current_scope.get_span + span_name = @engine.name_for(@keyword, @object) + @span.start_child(op: span_name) + end end - result - end - end - - def operation_name(query) - selected_op = query.selected_operation - if selected_op - [selected_op.operation_type, selected_op.name].compact.join(' ') - else - 'GraphQL Operation' + def finish + @span&.finish + end end end end diff --git a/lib/graphql/tracing/trace.rb b/lib/graphql/tracing/trace.rb index cca0964060..4017fdfe4c 100644 --- a/lib/graphql/tracing/trace.rb +++ b/lib/graphql/tracing/trace.rb @@ -23,12 +23,6 @@ def lex(query_string:) yield end - # @param query_str [String] - # @return [void] - def begin_parse(query_str); end; - # @param query_str [String] - # @return [void] - def end_parse(query_str); end; # @param query_string [String] # @return [void] def parse(query_string:) @@ -63,17 +57,6 @@ def analyze_query(query:) yield end - # This is the first event in the tracing lifecycle. - # Every Query is technically run _inside_ a {GraphQL::Multiplex}. - # @param multiplex [GraphQL::Execution::Multiplex] - # @return [void] - def begin_execute_multiplex(multiplex); end; - - # This is the last event of the tracing lifecycle. - # @param multiplex [GraphQL::Execution::Multiplex] - # @return [void] - def end_execute_multiplex(multiplex); end; - # This wraps an entire `.execute` call. # @param multiplex [GraphQL::Execution::Multiplex] # @return [void] diff --git a/spec/graphql/autoload_spec.rb b/spec/graphql/autoload_spec.rb index 702c209544..3be0e6c9cd 100644 --- a/spec/graphql/autoload_spec.rb +++ b/spec/graphql/autoload_spec.rb @@ -50,7 +50,7 @@ def self.eager_load! describe "loading nested files in the repo" do it "can load them individually" do files_to_load = Dir.glob("lib/**/tracing/*.rb") - assert_equal 28, files_to_load.size, "It found all the expected files" + assert_equal 29, files_to_load.size, "It found all the expected files" files_to_load.each do |file| require_path = file.sub("lib/", "").sub(".rb", "") stderr_and_stdout, _status = Open3.capture2e("ruby -Ilib -e 'require \"#{require_path}\"'") diff --git a/spec/graphql/tracing/active_support_notifications_trace_spec.rb b/spec/graphql/tracing/active_support_notifications_trace_spec.rb new file mode 100644 index 0000000000..9d5bd33817 --- /dev/null +++ b/spec/graphql/tracing/active_support_notifications_trace_spec.rb @@ -0,0 +1,67 @@ +# frozen_string_literal: true +require "spec_helper" + +if testing_rails? + describe GraphQL::Tracing::ActiveSupportNotificationsTrace do + class AsnSchema < GraphQL::Schema + class ThingSource < GraphQL::Dataloader::Source + def fetch(ids) + ids.map { |id| { name: "Thing #{id}" } } + end + end + + module Nameable + include GraphQL::Schema::Interface + field :name, String + def self.resolve_type(...) + Thing + end + end + + class Thing < GraphQL::Schema::Object + implements Nameable + end + + class Query < GraphQL::Schema::Object + field :nameable, Nameable + + def nameable + dataload(ThingSource, 1) + end + end + + query(Query) + trace_with GraphQL::Tracing::ActiveSupportNotificationsTrace + use GraphQL::Dataloader + orphan_types(Thing) + end + + it "emits tracing info" do + events = [] + callback = lambda { |name, started, finished, unique_id, payload| + events << [name, payload] + } + ActiveSupport::Notifications.subscribed(callback) do + AsnSchema.execute("{ nameable { name } }") + end + + expected_names = [ + (USING_C_PARSER ? "lex.graphql" : nil), + "parse.graphql", + "validate.graphql", + "analyze.graphql", + "authorized.graphql", + "execute_field.graphql", + "dataloader_source.graphql", + "execute_field.graphql", + "resolve_type.graphql", + "authorized.graphql", + "execute_field.graphql", + "execute.graphql" + ].compact + + assert_equal expected_names, events.map(&:first) + assert_equal [Hash], events.map(&:last).map(&:class).uniq + end + end +end diff --git a/spec/graphql/tracing/new_relic_trace_spec.rb b/spec/graphql/tracing/new_relic_trace_spec.rb index 62995149db..b8fa8d6529 100644 --- a/spec/graphql/tracing/new_relic_trace_spec.rb +++ b/spec/graphql/tracing/new_relic_trace_spec.rb @@ -140,13 +140,12 @@ class SchemaWithoutAuthorizedOrResolveType < GraphQL::Schema it "handles fiber pauses" do NewRelicTraceTest::SchemaWithTransactionName.execute("{ other { name } }") expected_steps = [ + (USING_C_PARSER ? "GraphQL/lex" : nil), "GraphQL/parse", - "FINISH GraphQL/parse", "GraphQL/execute", "GraphQL/analyze", "GraphQL/validate", - "FINISH GraphQL/validate", "FINISH GraphQL/analyze", "GraphQL/Authorized/Query", @@ -166,22 +165,18 @@ class SchemaWithoutAuthorizedOrResolveType < GraphQL::Schema "FINISH GraphQL/Query/other", "GraphQL/Authorized/Other", "FINISH GraphQL/Authorized/Other", - "GraphQL/Other/name", - "FINISH GraphQL/Other/name", - "FINISH GraphQL/execute" - ] + ].compact assert_equal expected_steps, NewRelic::EXECUTION_SCOPES end it "can skip authorized and resolve type" do NewRelicTraceTest::SchemaWithoutAuthorizedOrResolveType.execute("{ nameable { name } }") expected_steps = [ + (USING_C_PARSER ? "GraphQL/lex" : nil), "GraphQL/parse", - "FINISH GraphQL/parse", "GraphQL/execute", "GraphQL/analyze", "GraphQL/validate", - "FINISH GraphQL/validate", "FINISH GraphQL/analyze", # "GraphQL/Authorized/Query", # "FINISH GraphQL/Authorized/Query", @@ -191,10 +186,7 @@ class SchemaWithoutAuthorizedOrResolveType < GraphQL::Schema # "FINISH GraphQL/ResolveType/Nameable", # "GraphQL/Authorized/Other", # "FINISH GraphQL/Authorized/Other", - "GraphQL/Other/name", - "FINISH GraphQL/Other/name", - "FINISH GraphQL/execute" - ] + ].compact assert_equal expected_steps, NewRelic::EXECUTION_SCOPES end @@ -207,12 +199,11 @@ class SchemaWithoutAuthorizedOrResolveType < GraphQL::Schema it "handles lazies" do NewRelicTraceTest::SchemaWithTransactionName.execute("{ lazyNameable { name } }", context: { lazy: true }) expected_steps = [ + (USING_C_PARSER ? "GraphQL/lex" : nil), "GraphQL/parse", - "FINISH GraphQL/parse", "GraphQL/execute", "GraphQL/analyze", "GraphQL/validate", - "FINISH GraphQL/validate", "FINISH GraphQL/analyze", "GraphQL/Authorized/Query", "FINISH GraphQL/Authorized/Query", @@ -234,11 +225,7 @@ class SchemaWithoutAuthorizedOrResolveType < GraphQL::Schema "FINISH GraphQL/Authorized/Other", "GraphQL/Authorized/Other", "FINISH GraphQL/Authorized/Other", - - "GraphQL/Other/name", - "FINISH GraphQL/Other/name", - "FINISH GraphQL/execute", - ] + ].compact assert_equal expected_steps, NewRelic::EXECUTION_SCOPES end end diff --git a/spec/graphql/tracing/notifications_trace_spec.rb b/spec/graphql/tracing/notifications_trace_spec.rb index 50c42283e8..d33269c0dd 100644 --- a/spec/graphql/tracing/notifications_trace_spec.rb +++ b/spec/graphql/tracing/notifications_trace_spec.rb @@ -12,14 +12,23 @@ def int end end - class DummyEngine - def self.dispatched_events - @dispatched_events ||= [] + class DummyEngine < GraphQL::Tracing::NotificationsTrace::Adapter + class << self + def dispatched_events + @dispatched_events ||= [] + end end - def self.instrument(event, payload) - dispatched_events << [event, payload] - yield if block_given? + def instrument(event, payload = nil) + self.class.dispatched_events << [event, payload] + yield + end + + class Event < GraphQL::Tracing::NotificationsTrace::Adapter::Event + def start; end + def finish + DummyEngine.dispatched_events << [@name, @payload] + end end end @@ -41,30 +50,21 @@ class Schema < GraphQL::Schema NotificationsTraceTest::DummyEngine.dispatched_events.clear end - describe "Observing" do - it "dispatches the event to the notifications engine with suffixed key" do + it "dispatches the event to the notifications engine with a suffix" do NotificationsTraceTest::Schema.execute "query X { int }" dispatched_events = NotificationsTraceTest::DummyEngine.dispatched_events.to_h expected_event_keys = [ - 'execute_multiplex.graphql', - 'analyze_multiplex.graphql', - (USING_C_PARSER ? 'lex.graphql' : nil), - 'parse.graphql', - 'validate.graphql', - 'analyze_query.graphql', - 'execute_query.graphql', - 'authorized.graphql', - 'execute_field.graphql', - 'execute_query_lazy.graphql' + "execute.graphql", + (USING_C_PARSER ? "lex.graphql" : nil), + "parse.graphql", + "validate.graphql", + "analyze.graphql", + "authorized.graphql", + "execute_field.graphql" ].compact assert_equal expected_event_keys, dispatched_events.keys - - dispatched_events.each do |event, payload| - assert event.end_with?(".graphql") - assert payload.is_a?(Hash) - end end it "works with other tracers" do diff --git a/spec/graphql/tracing/sentry_trace_spec.rb b/spec/graphql/tracing/sentry_trace_spec.rb index 4ef1a708e2..c85ae2f4dd 100644 --- a/spec/graphql/tracing/sentry_trace_spec.rb +++ b/spec/graphql/tracing/sentry_trace_spec.rb @@ -58,13 +58,15 @@ class SchemaWithTransactionName < GraphQL::Schema end end - describe "When Sentry.with_child_span returns nil" do + describe "When Sentry.with_child_span / start_child returns nil" do it "does not initialize any spans" do Sentry.stub(:with_child_span, nil) do - SentryTraceTest::SchemaWithoutTransactionName.execute("{ int thing { str } }") - assert_equal [], Sentry::SPAN_DATA - assert_equal [], Sentry::SPAN_DESCRIPTIONS - assert_equal [], Sentry::SPAN_OPS + Sentry::DummySpan.stub(:start_child, nil) do + SentryTraceTest::SchemaWithoutTransactionName.execute("{ int thing { str } }") + assert_equal [], Sentry::SPAN_DATA + assert_equal [], Sentry::SPAN_DESCRIPTIONS + assert_equal [], Sentry::SPAN_OPS + end end end end @@ -72,17 +74,14 @@ class SchemaWithTransactionName < GraphQL::Schema it "sets the expected spans" do SentryTraceTest::SchemaWithoutTransactionName.execute("{ int thing { str } }") expected_span_ops = [ - "graphql.execute_multiplex", - "graphql.analyze_multiplex", + "graphql.execute", + "graphql.analyze", (USING_C_PARSER ? "graphql.lex" : nil), "graphql.parse", "graphql.validate", - "graphql.analyze", - "graphql.execute", "graphql.authorized.Query", "graphql.field.Query.thing", "graphql.authorized.Thing", - "graphql.execute" ].compact assert_equal expected_span_ops, Sentry::SPAN_OPS @@ -91,7 +90,7 @@ class SchemaWithTransactionName < GraphQL::Schema it "sets span descriptions for an anonymous query" do SentryTraceTest::SchemaWithoutTransactionName.execute("{ int }") - assert_equal ["query", "query"], Sentry::SPAN_DESCRIPTIONS + assert_equal ["query"], Sentry::SPAN_DESCRIPTIONS end it "sets span data for an anonymous query" do @@ -107,7 +106,7 @@ class SchemaWithTransactionName < GraphQL::Schema it "sets span descriptions for a named query" do SentryTraceTest::SchemaWithoutTransactionName.execute("query Ab { int }") - assert_equal ["query Ab", "query Ab"], Sentry::SPAN_DESCRIPTIONS + assert_equal ["query Ab"], Sentry::SPAN_DESCRIPTIONS end it "sets span data for a named query" do diff --git a/spec/support/new_relic.rb b/spec/support/new_relic.rb index d60de32bfe..392f3dd9fb 100644 --- a/spec/support/new_relic.rb +++ b/spec/support/new_relic.rb @@ -29,10 +29,6 @@ def initialize(name) @partial_name = name end - def name - "Controller/#{@partial_name}" - end - def finish EXECUTION_SCOPES << "FINISH #{@partial_name}" nil diff --git a/spec/support/sentry.rb b/spec/support/sentry.rb index abfc355f12..325a72ef2d 100644 --- a/spec/support/sentry.rb +++ b/spec/support/sentry.rb @@ -19,13 +19,21 @@ def self.utc_now Time.now.utc end + def self.get_current_scope + self + end + + def self.get_span + DummySpan + end + def self.with_child_span(**args, &block) SPAN_OPS << args[:op] - yield DummySpan.new + yield DummySpan end def self.configure_scope(&block) - yield DummyScope.new + yield DummyScope end def self.clear_all @@ -35,7 +43,8 @@ def self.clear_all TRANSACTION_NAMES.clear end - class DummySpan + module DummySpan + module_function def set_data(key, value) Sentry::SPAN_DATA << [key, value] end @@ -44,12 +53,17 @@ def set_description(description) Sentry::SPAN_DESCRIPTIONS << description end + def start_child(op:) + SPAN_OPS << op + end + def finish # no-op end end - class DummyScope + module DummyScope + module_function def set_transaction_name(name) TRANSACTION_NAMES << name end