only count time spent in queue as part of the http_server.queue span

If you have a request that spends 10ms in queue, and 5s being executed, you currently end up with these 2 spans in APM:

* `http_server.queue` (duration: 5.01s)
  * `rack.request` (duration: 5s)

However, that isn't really semantically correct. The queuing itself did not take 5.01s, the entire lifecycle of the request took 5.01s, with queueing making up 10ms of that time.

This is an attempt at resolving that inconsistency by introducing an outer `http_server.request` span, which contains `http_server.queue` and `rack.request` as sibling spans, rather than the current
parent/child relationship that exists between the 2 of them.

lib/datadog/tracing/contrib/rack/ext.rb

@@ -11,10 +11,12 @@ module Ext
           ENV_ANALYTICS_ENABLED = 'DD_TRACE_RACK_ANALYTICS_ENABLED'.freeze
           ENV_ANALYTICS_SAMPLE_RATE = 'DD_TRACE_RACK_ANALYTICS_SAMPLE_RATE'.freeze
           RACK_ENV_REQUEST_SPAN = 'datadog.rack_request_span'.freeze
+          SPAN_HTTP_SERVER_REQUEST = 'http_server.request'.freeze
           SPAN_HTTP_SERVER_QUEUE = 'http_server.queue'.freeze
           SPAN_REQUEST = 'rack.request'.freeze
           TAG_COMPONENT = 'rack'.freeze
           TAG_OPERATION_REQUEST = 'request'.freeze
+          TAG_OPERATION_HTTP_SERVER_REQUEST = 'request'.freeze
           TAG_OPERATION_HTTP_SERVER_QUEUE = 'queue'.freeze
           WEBSERVER_APP = 'webserver'.freeze
           DEFAULT_PEER_WEBSERVER_SERVICE_NAME = 'web-server'.freeze

lib/datadog/tracing/contrib/rack/middlewares.rb

@@ -35,22 +35,22 @@ def compute_queue_time(env)
             request_start = Contrib::Rack::QueueTime.get_request_start(env)
             return if request_start.nil?
 
-            frontend_span = Tracing.trace(
-              Ext::SPAN_HTTP_SERVER_QUEUE,
-              span_type: Tracing::Metadata::Ext::HTTP::TYPE_PROXY,
+            request_span = trace_http_server(
+              Ext::SPAN_HTTP_SERVER_REQUEST,
+              operation: Ext::TAG_OPERATION_HTTP_SERVER_REQUEST,
               start_time: request_start,
-              service: configuration[:web_service_name]
             )
 
-            # Tag this span as belonging to Rack
-            frontend_span.set_tag(Tracing::Metadata::Ext::TAG_COMPONENT, Ext::TAG_COMPONENT)
-            frontend_span.set_tag(Tracing::Metadata::Ext::TAG_OPERATION, Ext::TAG_OPERATION_HTTP_SERVER_QUEUE)
-            frontend_span.set_tag(Tracing::Metadata::Ext::TAG_KIND, Tracing::Metadata::Ext::SpanKind::TAG_SERVER)
-
-            # Set peer service (so its not believed to belong to this app)
-            frontend_span.set_tag(Tracing::Metadata::Ext::TAG_PEER_SERVICE, configuration[:web_service_name])
+            queue_span = trace_http_server(
+              Ext::SPAN_HTTP_SERVER_QUEUE,
+              operation: Ext::TAG_OPERATION_HTTP_SERVER_QUEUE,
+              start_time: request_start,
+            )
+            # finish the `queue` span now to record only the time spent *in queue*,
+            # excluding the time spent processing the request itself
+            queue_span.finish
 
-            frontend_span
+            request_span
           end
 
           def call(env)
@@ -242,6 +242,25 @@ def configuration
             Datadog.configuration.tracing[:rack]
           end
 
+          def trace_http_server(span_name, operation:, start_time:)
+            span = Tracing.trace(
+              span_name,
+              span_type: Tracing::Metadata::Ext::HTTP::TYPE_PROXY,
+              start_time: start_time,
+              service: configuration[:web_service_name]
+            )
+
+            # Tag this span as belonging to Rack
+            span.set_tag(Tracing::Metadata::Ext::TAG_COMPONENT, Ext::TAG_COMPONENT)
+            span.set_tag(Tracing::Metadata::Ext::TAG_OPERATION, operation)
+            span.set_tag(Tracing::Metadata::Ext::TAG_KIND, Tracing::Metadata::Ext::SpanKind::TAG_SERVER)
+
+            # Set peer service (so its not believed to belong to this app)
+            span.set_tag(Tracing::Metadata::Ext::TAG_PEER_SERVICE, configuration[:web_service_name])
+
+            span
+          end
+
           def parse_url(env, original_env)
             request_obj = ::Rack::Request.new(env)
 

spec/datadog/tracing/contrib/rack/configuration_spec.rb

@@ -69,27 +69,37 @@
     end
 
     shared_examples_for 'a Rack request with queuing' do
-      let(:queue_span) { spans.first }
-      let(:rack_span) { spans.last }
-
       it 'produces a queued Rack trace' do
         is_expected.to be_ok
 
         expect(trace.resource).to eq('GET 200')
 
-        expect(spans).to have(2).items
+        expect(spans).to have(3).items
+
+        server_request_span = spans[0]
+        server_queue_span = spans[1]
+        rack_span = spans[2]
 
         web_service_name = Datadog.configuration.tracing[:rack][:web_service_name]
-        expect(queue_span.name).to eq('http_server.queue')
-        expect(queue_span.span_type).to eq('proxy')
-        expect(queue_span.service).to eq(web_service_name)
-        expect(queue_span.start_time.to_i).to eq(queue_time)
-        expect(queue_span.get_tag(Datadog::Core::Runtime::Ext::TAG_LANG)).to be_nil
-        expect(queue_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_PEER_SERVICE)).to eq(web_service_name)
-        expect(queue_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_COMPONENT))
-          .to eq('rack')
-        expect(queue_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_OPERATION))
-          .to eq('queue')
+
+        expect(server_request_span.name).to eq('http_server.request')
+        expect(server_request_span.span_type).to eq('proxy')
+        expect(server_request_span.service).to eq(web_service_name)
+        expect(server_request_span.start_time.to_i).to eq(queue_time)
+        expect(server_request_span.get_tag(Datadog::Core::Runtime::Ext::TAG_LANG)).to be_nil
+        expect(server_request_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_PEER_SERVICE)).to eq(web_service_name)
+        expect(server_request_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_COMPONENT)).to eq('rack')
+        expect(server_request_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_OPERATION)).to eq('request')
+
+        expect(server_queue_span.name).to eq('http_server.queue')
+        expect(server_queue_span.span_type).to eq('proxy')
+        expect(server_queue_span.service).to eq(web_service_name)
+        expect(server_queue_span.start_time.to_i).to eq(queue_time)
+        expect(server_queue_span.get_tag(Datadog::Core::Runtime::Ext::TAG_LANG)).to be_nil
+        expect(server_queue_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_PEER_SERVICE)).to eq(web_service_name)
+        expect(server_queue_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_COMPONENT)).to eq('rack')
+        expect(server_queue_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_OPERATION)).to eq('queue')
+        expect(server_queue_span.parent_id).to eq(server_request_span.span_id)
 
         expect(rack_span.name).to eq('rack.request')
         expect(rack_span.span_type).to eq('web')
@@ -99,12 +109,9 @@
         expect(rack_span.get_tag('http.status_code')).to eq('200')
         expect(rack_span.get_tag('http.url')).to eq('/')
         expect(rack_span.status).to eq(0)
-        expect(rack_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_COMPONENT))
-          .to eq('rack')
-        expect(rack_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_OPERATION))
-          .to eq('request')
-
-        expect(queue_span.span_id).to eq(rack_span.parent_id)
+        expect(rack_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_COMPONENT)).to eq('rack')
+        expect(rack_span.get_tag(Datadog::Tracing::Metadata::Ext::TAG_OPERATION)).to eq('request')
+        expect(rack_span.parent_id).to eq(server_request_span.span_id)
       end
     end
 
@@ -154,6 +161,9 @@
             it_behaves_like 'a Rack request with queuing' do
               it 'sets the custom service name' do
                 is_expected.to be_ok
+
+                queue_span = spans.find { |s| s.name == Datadog::Tracing::Contrib::Rack::Ext::SPAN_HTTP_SERVER_QUEUE }
+
                 expect(queue_span.service).to eq(web_service_name)
               end
             end

spec/datadog/tracing/contrib/rack/distributed_spec.rb

@@ -93,25 +93,32 @@
           let(:rack_options) { super().merge(request_queuing: true, web_service_name: web_service_name) }
           let(:web_service_name) { 'frontend_web_server' }
 
-          let(:server_span) { spans.first }
-          let(:rack_span) { spans.last }
-
           before do
             header 'X-Request-Start', "t=#{Time.now.to_f}"
           end
 
           it 'contains a request_queuing span that belongs to the distributed trace' do
             is_expected.to be_ok
-            expect(spans).to have(2).items
 
-            expect(server_span.name).to eq('http_server.queue')
-            expect(server_span.trace_id).to eq(trace_id)
-            expect(server_span.parent_id).to eq(parent_id)
             expect(trace.sampling_priority).to eq(sampling_priority)
 
+            expect(spans).to have(3).items
+
+            server_request_span = spans[1]
+            server_queue_span = spans[0]
+            rack_span = spans[2]
+
+            expect(server_request_span.name).to eq('http_server.request')
+            expect(server_request_span.trace_id).to eq(trace_id)
+            expect(server_request_span.parent_id).to eq(parent_id)
+
+            expect(server_queue_span.name).to eq('http_server.queue')
+            expect(server_queue_span.trace_id).to eq(trace_id)
+            expect(server_queue_span.parent_id).to eq(server_request_span.span_id)
+
             expect(rack_span.name).to eq('rack.request')
             expect(rack_span.trace_id).to eq(trace_id)
-            expect(rack_span.parent_id).to eq(server_span.span_id)
+            expect(rack_span.parent_id).to eq(server_request_span.span_id)
           end
         end
       end

spec/datadog/tracing/contrib/rack/integration_test_spec.rb

@@ -314,22 +314,34 @@
 
           expect(trace.resource).to eq('GET 200')
 
-          expect(spans).to have(2).items
-
-          web_server_span = spans.find { |s| s.name == Datadog::Tracing::Contrib::Rack::Ext::SPAN_HTTP_SERVER_QUEUE }
-          rack_span = spans.find { |s| s.name == Datadog::Tracing::Contrib::Rack::Ext::SPAN_REQUEST }
-
-          expect(web_server_span).to be_root_span
-          expect(web_server_span.span_type).to eq('proxy')
-          expect(web_server_span.service).to eq('web-server')
-          expect(web_server_span.resource).to eq('http_server.queue')
-          expect(web_server_span.get_tag('component')).to eq('rack')
-          expect(web_server_span.get_tag('operation')).to eq('queue')
-          expect(web_server_span.get_tag('peer.service')).to eq('web-server')
-          expect(web_server_span.status).to eq(0)
-          expect(web_server_span.get_tag('span.kind'))
-            .to eq('server')
+          expect(spans).to have(3).items
 
+          server_request_span = spans[1]
+          server_queue_span = spans[0]
+          rack_span = spans[2]
+
+          expect(server_request_span).to be_root_span
+          expect(server_request_span.name).to eq(Datadog::Tracing::Contrib::Rack::Ext::SPAN_HTTP_SERVER_REQUEST)
+          expect(server_request_span.span_type).to eq('proxy')
+          expect(server_request_span.service).to eq('web-server')
+          expect(server_request_span.resource).to eq('http_server.request')
+          expect(server_request_span.get_tag('component')).to eq('rack')
+          expect(server_request_span.get_tag('operation')).to eq('request')
+          expect(server_request_span.get_tag('peer.service')).to eq('web-server')
+          expect(server_request_span.status).to eq(0)
+          expect(server_request_span.get_tag('span.kind')).to eq('server')
+
+          expect(server_queue_span.name).to eq(Datadog::Tracing::Contrib::Rack::Ext::SPAN_HTTP_SERVER_QUEUE)
+          expect(server_queue_span.span_type).to eq('proxy')
+          expect(server_queue_span.service).to eq('web-server')
+          expect(server_queue_span.resource).to eq('http_server.queue')
+          expect(server_queue_span.get_tag('component')).to eq('rack')
+          expect(server_queue_span.get_tag('operation')).to eq('queue')
+          expect(server_queue_span.get_tag('peer.service')).to eq('web-server')
+          expect(server_queue_span.status).to eq(0)
+          expect(server_queue_span.get_tag('span.kind')).to eq('server')
+
+          expect(rack_span.name).to eq(Datadog::Tracing::Contrib::Rack::Ext::SPAN_REQUEST)
           expect(rack_span.span_type).to eq('web')
           expect(rack_span.service).to eq(tracer.default_service)
           expect(rack_span.resource).to eq('GET 200')
@@ -338,8 +350,7 @@
           expect(rack_span.status).to eq(0)
           expect(rack_span.get_tag('component')).to eq('rack')
           expect(rack_span.get_tag('operation')).to eq('request')
-          expect(rack_span.get_tag('span.kind'))
-            .to eq('server')
+          expect(rack_span.get_tag('span.kind')).to eq('server')
         end
       end
     end
@@ -587,22 +598,35 @@
 
           expect(trace.resource).to eq('UserController#show')
 
-          expect(spans).to have(3).items
-
-          web_server_span = spans.find { |s| s.name == Datadog::Tracing::Contrib::Rack::Ext::SPAN_HTTP_SERVER_QUEUE }
-          rack_span = spans.find { |s| s.name == Datadog::Tracing::Contrib::Rack::Ext::SPAN_REQUEST }
-          nested_app_span = spans.find { |s| s.name == 'nested_app' }
-
-          expect(web_server_span).to be_root_span
-          expect(web_server_span.span_type).to eq('proxy')
-          expect(web_server_span.service).to eq('web-server')
-          expect(web_server_span.resource).to eq('http_server.queue')
-          expect(web_server_span.get_tag('component')).to eq('rack')
-          expect(web_server_span.get_tag('operation')).to eq('queue')
-          expect(web_server_span.get_tag('peer.service')).to eq('web-server')
-          expect(web_server_span.status).to eq(0)
-          expect(web_server_span.get_tag('span.kind')).to eq('server')
-
+          expect(spans).to have(4).items
+
+          server_request_span = spans[1]
+          server_queue_span = spans[0]
+          rack_span = spans[2]
+          nested_app_span = spans[3]
+
+          expect(server_request_span).to be_root_span
+          expect(server_request_span.name).to eq(Datadog::Tracing::Contrib::Rack::Ext::SPAN_HTTP_SERVER_REQUEST)
+          expect(server_request_span.span_type).to eq('proxy')
+          expect(server_request_span.service).to eq('web-server')
+          expect(server_request_span.resource).to eq('http_server.request')
+          expect(server_request_span.get_tag('component')).to eq('rack')
+          expect(server_request_span.get_tag('operation')).to eq('request')
+          expect(server_request_span.get_tag('peer.service')).to eq('web-server')
+          expect(server_request_span.status).to eq(0)
+          expect(server_request_span.get_tag('span.kind')).to eq('server')
+
+          expect(server_queue_span.name).to eq(Datadog::Tracing::Contrib::Rack::Ext::SPAN_HTTP_SERVER_QUEUE)
+          expect(server_queue_span.span_type).to eq('proxy')
+          expect(server_queue_span.service).to eq('web-server')
+          expect(server_queue_span.resource).to eq('http_server.queue')
+          expect(server_queue_span.get_tag('component')).to eq('rack')
+          expect(server_queue_span.get_tag('operation')).to eq('queue')
+          expect(server_queue_span.get_tag('peer.service')).to eq('web-server')
+          expect(server_queue_span.status).to eq(0)
+          expect(server_queue_span.get_tag('span.kind')).to eq('server')
+
+          expect(rack_span.name).to eq(Datadog::Tracing::Contrib::Rack::Ext::SPAN_REQUEST)
           expect(rack_span.span_type).to eq('web')
           expect(rack_span.service).to eq(tracer.default_service)
           expect(rack_span.resource).to eq('UserController#show')
@@ -613,6 +637,7 @@
           expect(rack_span.get_tag('operation')).to eq('request')
           expect(rack_span.get_tag('span.kind')).to eq('server')
 
+          expect(nested_app_span.name).to eq('nested_app')
           expect(nested_app_span.resource).to eq('UserController#show')
         end
       end