From 437094e7fcada76292a8dfaadd12825d50c82c48 Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Wed, 21 Jan 2026 12:09:44 -0300 Subject: [PATCH 1/3] Implementation --- lib/elastic_apm/graphql.rb | 6 ++++++ lib/elastic_apm/middleware.rb | 21 ++++++++++++++++++++- lib/elastic_apm/subscriber.rb | 17 +++++++++++++++++ lib/elastic_apm/transaction.rb | 2 +- 4 files changed, 44 insertions(+), 2 deletions(-) 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..76026a221 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,24 @@ 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' 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, From a8f8c3e4a75c1992ecefe18e7533ffdc42d82cee Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Wed, 21 Jan 2026 12:30:44 -0300 Subject: [PATCH 2/3] Guard queue time span and register custom subtypes --- lib/elastic_apm/middleware.rb | 1 + spec/fixtures/span_types.json | 12 ++++++++++++ 2 files changed, 13 insertions(+) diff --git a/lib/elastic_apm/middleware.rb b/lib/elastic_apm/middleware.rb index 76026a221..cef46f06e 100644 --- a/lib/elastic_apm/middleware.rb +++ b/lib/elastic_apm/middleware.rb @@ -117,6 +117,7 @@ def register_queue_time(transaction, env) transaction.timestamp -= queue_time_micros # 350ms before 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 diff --git a/spec/fixtures/span_types.json b/spec/fixtures/span_types.json index aa6e47f56..40ea45529 100644 --- a/spec/fixtures/span_types.json +++ b/spec/fixtures/span_types.json @@ -25,6 +25,18 @@ "__used_by": [ ] }, + "queue-time": { + "__description": "Queue time spent before request handling by rack middleware", + "__used_by": [ + "ruby" + ] + }, + "rack-stack": { + "__description": "Time spent in Rack stack before being handled by GraphQL", + "__used_by": [ + "ruby" + ] + }, "controller": { "__description": "Deprecated: use app.internal instead", "__used_by": [ From 6d1b8006c46a4c63dc69e117692db5b9da8aec9c Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Fri, 23 Jan 2026 11:47:08 -0300 Subject: [PATCH 3/3] Update subtype description --- spec/fixtures/span_types.json | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/spec/fixtures/span_types.json b/spec/fixtures/span_types.json index 40ea45529..fb1ee3388 100644 --- a/spec/fixtures/span_types.json +++ b/spec/fixtures/span_types.json @@ -26,13 +26,13 @@ ] }, "queue-time": { - "__description": "Queue time spent before request handling by rack middleware", + "__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 stack before being handled by GraphQL", + "__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" ]