module GraphQL::Tracing::PerfettoTrace
This produces a trace file for inspecting in the Perfetto Trace Viewer.
To get the file, call write on the trace.
Use “trace modes” to configure this to run on command or on a sample of traffic.
Examples
Example: Writing trace output
result = MySchema.execute(...) result.query.trace.write(file: "tmp/trace.dump")
Example: Running this instrumenter when trace: true is present in the request
class MySchema < GraphQL::Schema # Only run this tracer when `context[:trace_mode]` is `:trace` trace_with GraphQL::Tracing::Perfetto, mode: :trace end # In graphql_controller.rb: context[:trace_mode] = params[:trace] ? :trace : nil result = MySchema.execute(query_str, context: context, variables: variables, ...) if context[:trace_mode] == :trace result.trace.write(file: ...) end
Constants
- ACTIVE_SUPPORT_NOTIFICATIONS_CATEGORY_IIDS
- ANON_CLASS_NAME
- AUTHORIZED_CATEGORY_IIDS
- CounterDescriptor
- DATALOADER_CATEGORY_IIDS
- DA_ARGUMENTS_IID
- DA_DEBUG_INSPECT_CLASS_IID
- DA_DEBUG_INSPECT_FOR_IID
- DA_FETCH_KEYS_IID
- DA_OBJECT_IID
- DA_RESULT_IID
- DA_STR_VAL_NIL_IID
- DEBUG_INSPECT_CATEGORY_IIDS
- DEBUG_INSPECT_EVENT_NAME_IID
- DebugAnnotation
- DebugAnnotationName
- EventCategory
- EventName
- FIELD_EXECUTE_CATEGORY_IIDS
- InternedData
- InternedString
- PROTOBUF_AVAILABLE
-
TODOs: - Make debug annotations visible on both parts when dataloader is involved
- RESOLVE_TYPE_CATEGORY_IIDS
- REVERSE_DEBUG_NAME_LOOKUP
- Trace
- TracePacket
- TrackDescriptor
- TrackEvent
Public Class Methods
Source
# File lib/graphql/tracing/perfetto_trace.rb, line 53 def self.included(_trace_class) if !PROTOBUF_AVAILABLE raise "#{self} can't be used because the `google-protobuf` gem wasn't available. Add it to your project, then try again." end end
Source
# File lib/graphql/tracing/perfetto_trace.rb, line 91 def initialize(active_support_notifications_pattern: nil, save_profile: false, **_rest) super @active_support_notifications_pattern = active_support_notifications_pattern @save_profile = save_profile query = if @multiplex @multiplex.queries.first else @query # could still be nil in some initializations end @detailed_trace = query&.schema&.detailed_trace || DetailedTrace @create_debug_annotations = if (ctx = query&.context).nil? || (ctx_debug = ctx[:detailed_trace_debug]).nil? @detailed_trace.debug? else ctx_debug end @arguments_filter = if (ctx = query&.context) && (dtf = ctx[:detailed_trace_filter]) dtf elsif defined?(ActiveSupport::ParameterFilter) fp = if defined?(Rails) && Rails.application && (app_config = Rails.application.config.filter_parameters).present? && !app_config.empty? app_config elsif ActiveSupport.respond_to?(:filter_parameters) ActiveSupport.filter_parameters else EmptyObjects::EMPTY_ARRAY end ActiveSupport::ParameterFilter.new(fp, mask: ArgumentsFilter::FILTERED) else ArgumentsFilter.new end Fiber[:graphql_flow_stack] = nil @sequence_id = object_id @pid = Process.pid @flow_ids = Hash.new { |h, source_inst| h[source_inst] = [] }.compare_by_identity @new_interned_event_names = {} @interned_event_name_iids = Hash.new { |h, k| new_id = 100 + h.size @new_interned_event_names[k] = new_id h[k] = new_id } @source_name_iids = Hash.new do |h, source_class| h[source_class] = @interned_event_name_iids[source_class.name || ANON_CLASS_NAME] end.compare_by_identity @auth_name_iids = Hash.new do |h, graphql_type| h[graphql_type] = @interned_event_name_iids["Authorize: #{graphql_type.graphql_name}"] end.compare_by_identity @resolve_type_name_iids = Hash.new do |h, graphql_type| h[graphql_type] = @interned_event_name_iids["Resolve Type: #{graphql_type.graphql_name}"] end.compare_by_identity @new_interned_da_names = {} @interned_da_name_ids = Hash.new { |h, k| next_id = 100 + h.size @new_interned_da_names[k] = next_id h[k] = next_id } @new_interned_da_string_values = {} @interned_da_string_values = Hash.new do |h, k| new_id = 100 + h.size @new_interned_da_string_values[k] = new_id h[k] = new_id end @class_name_iids = Hash.new do |h, k| h[k] = @interned_da_string_values[k.name || ANON_CLASS_NAME] end.compare_by_identity @starting_objects = GC.stat(:total_allocated_objects) @objects_counter_id = :objects_counter.object_id @fibers_counter_id = :fibers_counter.object_id @fields_counter_id = :fields_counter.object_id @counts_objects = [@objects_counter_id] @counts_objects_and_fields = [@objects_counter_id, @fields_counter_id] @counts_fibers = [@fibers_counter_id] @counts_fibers_and_objects = [@fibers_counter_id, @objects_counter_id] @begin_validate = nil @begin_time = nil @packets = [] @packets << TracePacket.new( track_descriptor: TrackDescriptor.new( uuid: tid, name: "Main Thread", child_ordering: TrackDescriptor::ChildTracksOrdering::CHRONOLOGICAL, ), first_packet_on_sequence: true, previous_packet_dropped: true, trusted_packet_sequence_id: @sequence_id, sequence_flags: 3, ) @packets << TracePacket.new( interned_data: InternedData.new( event_categories: [ EventCategory.new(name: "Dataloader", iid: DATALOADER_CATEGORY_IIDS.first), EventCategory.new(name: "Field Execution", iid: FIELD_EXECUTE_CATEGORY_IIDS.first), EventCategory.new(name: "ActiveSupport::Notifications", iid: ACTIVE_SUPPORT_NOTIFICATIONS_CATEGORY_IIDS.first), EventCategory.new(name: "Authorized", iid: AUTHORIZED_CATEGORY_IIDS.first), EventCategory.new(name: "Resolve Type", iid: RESOLVE_TYPE_CATEGORY_IIDS.first), EventCategory.new(name: "Debug Inspect", iid: DEBUG_INSPECT_CATEGORY_IIDS.first), ], debug_annotation_names: [ *REVERSE_DEBUG_NAME_LOOKUP.map { |(iid, name)| DebugAnnotationName.new(name: name, iid: iid) }, DebugAnnotationName.new(name: "inspect instance of", iid: DA_DEBUG_INSPECT_CLASS_IID), DebugAnnotationName.new(name: "inspecting for", iid: DA_DEBUG_INSPECT_FOR_IID) ], debug_annotation_string_values: [ InternedString.new(str: "(nil)", iid: DA_STR_VAL_NIL_IID), ], event_names: [ EventName.new(name: "#{(@detailed_trace.is_a?(Class) ? @detailed_trace : @detailed_trace.class).name}#inspect_object", iid: DEBUG_INSPECT_EVENT_NAME_IID) ], ), trusted_packet_sequence_id: @sequence_id, sequence_flags: 2, ) @main_fiber_id = fid @packets << track_descriptor_packet(tid, fid, "Main Fiber") @packets << track_descriptor_packet(tid, @objects_counter_id, "Allocated Objects", counter: {}) @packets << trace_packet( type: TrackEvent::Type::TYPE_COUNTER, track_uuid: @objects_counter_id, counter_value: count_allocations, ) @packets << track_descriptor_packet(tid, @fibers_counter_id, "Active Fibers", counter: {}) @fibers_count = 0 @packets << trace_packet( type: TrackEvent::Type::TYPE_COUNTER, track_uuid: @fibers_counter_id, counter_value: count_fibers(0), ) @packets << track_descriptor_packet(tid, @fields_counter_id, "Resolved Fields", counter: {}) @fields_count = -1 @packets << trace_packet( type: TrackEvent::Type::TYPE_COUNTER, track_uuid: @fields_counter_id, counter_value: count_fields, ) end
Parameters
-
active_support_notifications_pattern(String, RegExp, false) — A filter forActiveSupport::Notifications, if it’s present. Orfalseto skip subscribing.
Public Instance Methods
# File lib/graphql/tracing/perfetto_trace.rb, line 304 def begin_analyze_multiplex(m, analyzers) @packets << trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], name: "Analysis") { [ payload_to_debug("analyzers_count", analyzers.size), payload_to_debug("analyzers", analyzers), ] } super end
Source
# File lib/graphql/tracing/perfetto_trace.rb, line 468 def begin_dataloader(dl) @packets << trace_packet( type: TrackEvent::Type::TYPE_COUNTER, track_uuid: @fibers_counter_id, counter_value: count_fibers(1), ) @did = fid @packets << track_descriptor_packet(@main_fiber_id, @did, "Dataloader Fiber ##{@did}") super end
# File lib/graphql/tracing/perfetto_trace.rb, line 488 def begin_dataloader_source(source) fds = @flow_ids[source] fds_copy = fds.dup fds.clear packet = trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, name_iid: @source_name_iids[source.class], category_iids: DATALOADER_CATEGORY_IIDS, flow_ids: fds_copy, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations]) { [ payload_to_debug(nil, source.pending.values, iid: DA_FETCH_KEYS_IID, intern_value: true), *(source.instance_variables - [:@pending, :@fetching, :@results, :@dataloader]).map { |iv| payload_to_debug(iv.to_s, source.instance_variable_get(iv), intern_value: true) } ] } @packets << packet fiber_flow_stack << packet super end
# File lib/graphql/tracing/perfetto_trace.rb, line 267 def begin_execute_field(field, object, arguments, query) packet = trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, name: query.context.current_path&.join(".") || field.path, category_iids: FIELD_EXECUTE_CATEGORY_IIDS, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], ) @packets << packet fiber_flow_stack << packet super end
# File lib/graphql/tracing/perfetto_trace.rb, line 556 def begin_resolve_type(type, value, context) packet = trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, category_iids: RESOLVE_TYPE_CATEGORY_IIDS, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], name_iid: @resolve_type_name_iids[type], ) @packets << packet fiber_flow_stack << packet super end
# File lib/graphql/tracing/perfetto_trace.rb, line 351 def begin_validate(query, validate) @begin_validate = trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], name: "Validate") { [payload_to_debug("validate?", validate)] } @packets << @begin_validate super end
Source
# File lib/graphql/tracing/perfetto_trace.rb, line 456 def dataloader_fiber_exit @packets << trace_packet( type: TrackEvent::Type::TYPE_INSTANT, track_uuid: fid, name: "Fiber Exit", category_iids: DATALOADER_CATEGORY_IIDS, extra_counter_track_uuids: @counts_fibers, extra_counter_values: [count_fibers(-1)], ) super end
# File lib/graphql/tracing/perfetto_trace.rb, line 437 def dataloader_fiber_resume(source) @packets << trace_packet( type: TrackEvent::Type::TYPE_INSTANT, track_uuid: fid, name: "Fiber Resume", category_iids: DATALOADER_CATEGORY_IIDS, ) ls = fiber_flow_stack.pop @packets << packet = TracePacket.new( timestamp: ts, track_event: dup_with(ls.track_event, { type: TrackEvent::Type::TYPE_SLICE_BEGIN }), trusted_packet_sequence_id: @sequence_id, ) fiber_flow_stack << packet super end
# File lib/graphql/tracing/perfetto_trace.rb, line 415 def dataloader_fiber_yield(source) ls = fiber_flow_stack.last if (flow_id = ls.track_event.flow_ids.first) # got it else flow_id = ls.track_event.name.object_id ls.track_event = dup_with(ls.track_event, {flow_ids: [flow_id] }, delete_counters: true) end @flow_ids[source] << flow_id @packets << trace_packet( type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, ) @packets << trace_packet( type: TrackEvent::Type::TYPE_INSTANT, track_uuid: fid, name: "Fiber Yield", category_iids: DATALOADER_CATEGORY_IIDS, ) super end
# File lib/graphql/tracing/perfetto_trace.rb, line 389 def dataloader_spawn_execution_fiber(jobs) @packets << trace_packet( type: TrackEvent::Type::TYPE_INSTANT, track_uuid: fid, name: "Create Execution Fiber", category_iids: DATALOADER_CATEGORY_IIDS, extra_counter_track_uuids: @counts_fibers_and_objects, extra_counter_values: [count_fibers(1), count_allocations] ) @packets << track_descriptor_packet(@did, fid, "Exec Fiber ##{fid}") super end
# File lib/graphql/tracing/perfetto_trace.rb, line 402 def dataloader_spawn_source_fiber(pending_sources) @packets << trace_packet( type: TrackEvent::Type::TYPE_INSTANT, track_uuid: fid, name: "Create Source Fiber", category_iids: DATALOADER_CATEGORY_IIDS, extra_counter_track_uuids: @counts_fibers_and_objects, extra_counter_values: [count_fibers(1), count_allocations] ) @packets << track_descriptor_packet(@did, fid, "Source Fiber ##{fid}") super end
# File lib/graphql/tracing/perfetto_trace.rb, line 319 def end_analyze_multiplex(m, analyzers) end_ts = ts @packets << trace_packet( timestamp: end_ts, type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], ) super end
Source
# File lib/graphql/tracing/perfetto_trace.rb, line 479 def end_dataloader(dl) @packets << trace_packet( type: TrackEvent::Type::TYPE_COUNTER, track_uuid: @fibers_counter_id, counter_value: count_fibers(-1), ) super end
# File lib/graphql/tracing/perfetto_trace.rb, line 513 def end_dataloader_source(source) end_ts = ts @packets << trace_packet( timestamp: end_ts, type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], ) fiber_flow_stack.pop super end
# File lib/graphql/tracing/perfetto_trace.rb, line 281 def end_execute_field(field, object, arguments, query, app_result) end_ts = ts start_field = fiber_flow_stack.pop if @create_debug_annotations start_field.track_event = dup_with(start_field.track_event,{ debug_annotations: [ payload_to_debug(nil, (object.is_a?(GraphQL::Schema::Object) ? object.object : object), iid: DA_OBJECT_IID, intern_value: true), payload_to_debug(nil, arguments, iid: DA_ARGUMENTS_IID), payload_to_debug(nil, app_result, iid: DA_RESULT_IID, intern_value: true) ] }) end @packets << trace_packet( timestamp: end_ts, type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, extra_counter_track_uuids: @counts_objects_and_fields, extra_counter_values: [count_allocations, count_fields], ) super end
# File lib/graphql/tracing/perfetto_trace.rb, line 570 def end_resolve_type(type, value, context, resolved_type) end_ts = ts @packets << trace_packet( timestamp: end_ts, type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], ) rt_begin = fiber_flow_stack.pop if @create_debug_annotations rt_begin.track_event = dup_with(rt_begin.track_event, { debug_annotations: [payload_to_debug("resolved_type", resolved_type, intern_value: true)] }) end super end
# File lib/graphql/tracing/perfetto_trace.rb, line 365 def end_validate(query, validate, validation_errors) end_ts = ts @packets << trace_packet( timestamp: end_ts, type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], ) if @create_debug_annotations new_bv_track_event = dup_with( @begin_validate.track_event, { debug_annotations: [ @begin_validate.track_event.debug_annotations.first, payload_to_debug("valid?", validation_errors.empty?) ] } ) @begin_validate.track_event = new_bv_track_event end super end
# File lib/graphql/tracing/perfetto_trace.rb, line 237 def execute_multiplex(multiplex:) if defined?(ActiveSupport::Notifications) && @active_support_notifications_pattern != false subscribe_to_active_support_notifications(@active_support_notifications_pattern) end @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" ) { [ payload_to_debug("query_string", multiplex.queries.map(&:sanitized_query_string).join("\n\n")) ] } result = super @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 multiplex.schema.detailed_trace.save_trace(@operation_name, duration_ms, begin_ts, Trace.encode(Trace.new(packet: @packets))) end end
Source
# File lib/graphql/tracing/perfetto_trace.rb, line 331 def parse(query_string:) @packets << trace_packet( type: TrackEvent::Type::TYPE_SLICE_BEGIN, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], name: "Parse" ) result = super end_ts = ts @packets << trace_packet( timestamp: end_ts, type: TrackEvent::Type::TYPE_SLICE_END, track_uuid: fid, extra_counter_track_uuids: @counts_objects, extra_counter_values: [count_allocations], ) result end
# File lib/graphql/tracing/perfetto_trace.rb, line 599 def write(file:, debug_json: false) trace = Trace.new( packet: @packets, ) data = if debug_json small_json = Trace.encode_json(trace) JSON.pretty_generate(JSON.parse(small_json)) else Trace.encode(trace) end if file File.write(file, data, mode: 'wb') nil else data end end
Dump protobuf output in the specified file.
Parameters
-
file(String) — path to a file in a directory that already exists -
debug_json(Boolean) — True to print JSON instead of binary
Returns
-
nil, String, Hash— Iffilewas given,nil. Iffilewasnil, a Hash ifdebug_json: true, else binary data.