Track request queue time based on available request headers

CHANGELOG.md

@@ -3,6 +3,12 @@
 ### Unreleased
 
 * Measure render collection
+* Requests now report the time they have been queued by the proxy before reaching the application.
+
+  A section with the kind `queue` reports the time between the timestamp set by the HTTP proxy
+  when the request was received and the time the application started processing the request.
+
+  This time is also included into the total runtime of the request.
 
 ## 1.8.1 (2024-10-17)
 

lib/rorvswild/agent.rb

@@ -114,8 +114,8 @@ def measure_job(name, parameters: nil, &block)
       end
     end
 
-    def start_request
-      current_data || initialize_data
+    def start_request(queue_time_ms = 0)
+      current_data || initialize_data(queue_time_ms)
     end
 
     def stop_request
@@ -195,9 +195,9 @@ def ignored_exception?(exception)
 
     private
 
-    def initialize_data
+    def initialize_data(queue_time_ms = 0)
       Thread.current[:rorvswild_data] = {
-        started_at: RorVsWild.clock_milliseconds,
+        started_at: RorVsWild.clock_milliseconds - queue_time_ms,
         gc_section: Section.start_gc_timing,
         environment: Host.to_h,
         section_stack: [],

lib/rorvswild/plugin/middleware.rb

@@ -3,6 +3,49 @@
 module RorVsWild
   module Plugin
     class Middleware
+      module RequestQueueTime
+
+        ACCEPTABLE_HEADERS = [
+          'HTTP_X_REQUEST_START',
+          'HTTP_X_QUEUE_START',
+          'HTTP_X_MIDDLEWARE_START'
+        ].freeze
+
+        MINIMUM_TIMESTAMP = 1577836800.freeze # 2020/01/01 UTC
+        DIVISORS = [1_000_000, 1_000, 1].freeze
+
+        def parse_queue_time_header(env)
+          return unless env
+
+          earliest = nil
+
+          ACCEPTABLE_HEADERS.each do |header|
+            if (header_value = env[header])
+              timestamp = parse_timestamp(header_value.delete_prefix("t="))
+              if timestamp && (!earliest || timestamp < earliest)
+                earliest = timestamp
+              end
+            end
+          end
+
+          [earliest, Time.now.to_f].min if earliest
+        end
+
+        private
+
+        def parse_timestamp(timestamp)
+          timestamp = timestamp.to_f
+          return unless timestamp.finite?
+
+          DIVISORS.each do |divisor|
+            t = timestamp / divisor
+            return t if t > MINIMUM_TIMESTAMP
+          end
+        end
+      end
+
+      include RequestQueueTime
+
       def self.setup
         return if @installed
         Rails.application.config.middleware.unshift(RorVsWild::Plugin::Middleware, nil) if defined?(Rails)
@@ -14,8 +57,10 @@ def initialize(app, config)
       end
 
       def call(env)
-        RorVsWild.agent.start_request
+        queue_time_ms = calculate_queue_time(env)
+        RorVsWild.agent.start_request(queue_time_ms || 0)
         RorVsWild.agent.current_data[:path] = env["ORIGINAL_FULLPATH"]
+        add_queue_time_section(queue_time_ms)
         section = RorVsWild::Section.start
         section.file, section.line = rails_engine_location
         section.commands << "Rails::Engine#call"
@@ -28,6 +73,25 @@ def call(env)
 
       private
 
+      def add_queue_time_section(queue_time_ms)
+        return unless queue_time_ms
+
+        section = Section.new
+        section.stop
+        section.total_ms = queue_time_ms
+        section.gc_time_ms = 0
+        section.file = "request-queue"
+        section.line = 0
+        section.kind = "queue"
+        RorVsWild.agent.add_section(section)
+      end
+
+      def calculate_queue_time(env)
+        queue_time_from_header = parse_queue_time_header(env)
+
+        ((Time.now.to_f - queue_time_from_header) * 1000).round if queue_time_from_header
+      end
+
       def rails_engine_location
         @rails_engine_location = ::Rails::Engine.instance_method(:call).source_location
       end

test/plugin/middleware_test.rb

@@ -14,5 +14,71 @@ def test_callback
     assert_equal(1, agent.current_data[:sections].size)
     assert_equal("Rails::Engine#call", agent.current_data[:sections][0].command)
   end
-end
 
+  def test_queue_time_section
+    agent # Load agent
+    request = {"HTTP_X_REQUEST_START" => unix_timestamp_seconds.to_s}
+    app = mock(call: nil)
+    middleware = RorVsWild::Plugin::Middleware.new(app, nil)
+    middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12])
+
+    middleware.call(request)
+
+    assert_equal(2, agent.current_data[:sections].size)
+    queue_time_section = agent.current_data[:sections][0]
+    assert_equal "request-queue", queue_time_section.file
+    assert_equal "queue", queue_time_section.kind
+    assert_equal 0, queue_time_section.line
+    assert_equal 0, queue_time_section.gc_time_ms
+  end
+
+  def test_queue_time_secs
+    agent # Load agent
+    request_start = unix_timestamp_seconds - 0.123
+    request = {"HTTP_X_REQUEST_START" => request_start.to_s}
+    app = mock(call: nil)
+    middleware = RorVsWild::Plugin::Middleware.new(app, nil)
+    middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12])
+
+    middleware.call(request)
+
+    assert_equal(2, agent.current_data[:sections].size)
+    queue_time_section = agent.current_data[:sections][0]
+    assert_in_delta(123, queue_time_section.total_ms, 10)
+  end
+
+  def test_queue_time_millis
+    agent # Load agent
+    request_start = unix_timestamp_seconds * 1000 - 234
+    request = { "HTTP_X_QUEUE_START" => request_start.to_s }
+    app = mock(call: nil)
+    middleware = RorVsWild::Plugin::Middleware.new(app, nil)
+    middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12])
+
+    middleware.call(request)
+
+    assert_equal(2, agent.current_data[:sections].size)
+    queue_time_section = agent.current_data[:sections][0]
+    assert_in_delta(234, queue_time_section.total_ms, 10)
+  end
+
+  def test_queue_time_micros
+    agent # Load agent
+    request_start = unix_timestamp_seconds * 1_000_000 - 345_000
+    request = { "HTTP_X_MIDDLEWARE_START" => request_start.to_s }
+    app = mock(call: nil)
+    middleware = RorVsWild::Plugin::Middleware.new(app, nil)
+    middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12])
+    middleware.call(request)
+
+    assert_equal(2, agent.current_data[:sections].size)
+    queue_time_section = agent.current_data[:sections][0]
+    assert_in_delta(345, queue_time_section.total_ms, 10)
+  end
+
+  private
+
+  def unix_timestamp_seconds
+    Time.now.to_f
+  end
+end