FEATURE: track request queueing as early as possible

lib/middleware/request_tracker.rb

@@ -129,7 +129,8 @@ class Middleware::RequestTracker
       is_background: !!(request.path =~ /^\/message-bus\// || request.path =~ /\/topics\/timings/),
       is_mobile: helper.is_mobile?,
       track_view: track_view,
-      timing: timing
+      timing: timing,
+      queue_seconds: env['REQUEST_QUEUE_SECONDS']
     }.tap do |h|
       h[:user_agent] = env['HTTP_USER_AGENT'] if h[:is_crawler]
     end
@@ -158,6 +159,15 @@ class Middleware::RequestTracker
   def call(env)
     result = nil
     log_request = true
+
+    # doing this as early as possible so we have an
+    # accurate counter
+    if queue_start = env['HTTP_X_REQUEST_START']
+      queue_start = queue_start.split("t=")[1].to_f
+      queue_time = (Time.now.to_f - queue_start)
+      env['REQUEST_QUEUE_SECONDS'] = queue_time
+    end
+
     request = Rack::Request.new(env)
 
     if rate_limit(request)

spec/components/middleware/request_tracker_spec.rb

@@ -265,8 +265,15 @@ describe Middleware::RequestTracker do
       # ensure pg is warmed up with the select 1 query
       User.where(id: -100).pluck(:id)
 
+      freeze_time
+      start = Time.now.to_f
+
+      freeze_time 1.minute.from_now
+
       tracker = Middleware::RequestTracker.new(app([200, {}, []], sql_calls: 2, redis_calls: 2))
-      tracker.call(env)
+      tracker.call(env("HTTP_X_REQUEST_START" => "t=#{start}"))
+
+      expect(@data[:queue_seconds]).to eq(60)
 
       timing = @data[:timing]
       expect(timing[:total_duration]).to be > 0