DIGIT-2819 Add Rack Stack span and normalize Queue Time span type/subtype

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])}"

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

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

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,

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": [