diff --git a/lib/elastic_apm/graphql.rb b/lib/elastic_apm/graphql.rb index 30127d2a3..997b4adfa 100644 --- a/lib/elastic_apm/graphql.rb +++ b/lib/elastic_apm/graphql.rb @@ -53,6 +53,12 @@ def self.trace(key, data) return yield unless KEYS_TO_NAME.key?(key) return yield unless (transaction = ElasticAPM.current_transaction) + # Finalize Rack Stack span on first GraphQL event + if transaction.rack_stack_span && key == 'lex' + ElasticAPM.end_span(transaction.rack_stack_span) + transaction.rack_stack_span = nil + end + if key == 'execute_query' transaction.name = "#{PREFIX}#{query_name(data[:query])}" diff --git a/lib/elastic_apm/middleware.rb b/lib/elastic_apm/middleware.rb index a6c166981..cef46f06e 100644 --- a/lib/elastic_apm/middleware.rb +++ b/lib/elastic_apm/middleware.rb @@ -35,6 +35,7 @@ def call(env) end register_queue_time(transaction, env) if transaction + start_rack_stack_span(transaction) if transaction resp = @app.call env rescue InternalError @@ -45,6 +46,12 @@ def call(env) raise ensure if transaction + # Cleanup rack_stack_span if still open (request failed before controller) + if transaction.rack_stack_span + ElasticAPM.end_span(transaction.rack_stack_span) + transaction.rack_stack_span = nil + end + if resp status, headers, _body = resp transaction.add_response(status, headers: headers.dup) @@ -109,12 +116,25 @@ def register_queue_time(transaction, env) transaction.clock_start -= queue_time_micros transaction.timestamp -= queue_time_micros # 350ms before - span = ElasticAPM.start_span 'Queue Time', 'queue', subtype: 'nginx', action: 'awaiting' + span = ElasticAPM.start_span 'Queue Time', 'app', subtype: 'queue-time', action: 'awaiting' + return unless span span.clock_start = transaction.clock_start span.timestamp = transaction.timestamp ElasticAPM.end_span(span) end + + def start_rack_stack_span(transaction) + span = ElasticAPM.start_span( + 'Rack Stack', + 'app', + subtype: 'rack-stack', + action: 'processing' + ) + return unless span + + transaction.rack_stack_span = span + end end end diff --git a/lib/elastic_apm/subscriber.rb b/lib/elastic_apm/subscriber.rb index 9537764bd..4c7cf88f9 100644 --- a/lib/elastic_apm/subscriber.rb +++ b/lib/elastic_apm/subscriber.rb @@ -25,6 +25,12 @@ module ElasticAPM class Subscriber include Logging + # Events that indicate the start of "real work" (end of rack middleware stack) + RACK_STACK_ENDING_EVENTS = %w[ + process_action.action_controller + endpoint_run.grape + ].freeze + def initialize(agent) @agent = agent @normalizers = Normalizers.build(agent.config) @@ -49,6 +55,9 @@ def unregister! def start(name, id, payload) return unless (transaction = @agent.current_transaction) + # Finalize Rack Stack span when first "real work" event starts + finish_rack_stack_span_if_needed(transaction, name) + normalized = @normalizers.normalize(transaction, name, payload) span = @@ -93,5 +102,13 @@ def finish(name, id, payload) def notifications_regex @notifications_regex ||= /(#{@normalizers.keys.join('|')})/ end + + def finish_rack_stack_span_if_needed(transaction, event_name) + return unless transaction.rack_stack_span + return unless RACK_STACK_ENDING_EVENTS.include?(event_name) + + ElasticAPM.end_span(transaction.rack_stack_span) + transaction.rack_stack_span = nil + end end end diff --git a/lib/elastic_apm/transaction.rb b/lib/elastic_apm/transaction.rb index 332b4ff5d..798a4b41c 100644 --- a/lib/elastic_apm/transaction.rb +++ b/lib/elastic_apm/transaction.rb @@ -87,7 +87,7 @@ def initialize( end # rubocop:enable Metrics/ParameterLists - attr_accessor :name, :type, :result, :outcome, :clock_start, :timestamp + attr_accessor :name, :type, :result, :outcome, :clock_start, :timestamp, :rack_stack_span attr_reader( :breakdown_metrics, diff --git a/spec/fixtures/span_types.json b/spec/fixtures/span_types.json index aa6e47f56..fb1ee3388 100644 --- a/spec/fixtures/span_types.json +++ b/spec/fixtures/span_types.json @@ -25,6 +25,18 @@ "__used_by": [ ] }, + "queue-time": { + "__description": "Time between the request start timestamp (X-Request-Start from nginx) and when Rack processing begins; include reverse-proxy buffering and Puma queueing.", + "__used_by": [ + "ruby" + ] + }, + "rack-stack": { + "__description": "Time spent in Rack/framework middleware and routing after Rack starts, until the request reaches the handler (e.g. Rails controller and GraphQL).", + "__used_by": [ + "ruby" + ] + }, "controller": { "__description": "Deprecated: use app.internal instead", "__used_by": [