diff --git a/docs/GettingStarted.md b/docs/GettingStarted.md index ebec956d338..a68b84f46bf 100644 --- a/docs/GettingStarted.md +++ b/docs/GettingStarted.md @@ -47,6 +47,7 @@ For descriptions of terminology used in APM, take a look at the [official docume - [Sampling](#sampling) - [Priority sampling](#priority-sampling) - [Distributed tracing](#distributed-tracing) + - [HTTP request queuing](#http-request-queuing) - [Processing pipeline](#processing-pipeline) - [Filtering](#filtering) - [Processing](#processing) @@ -582,6 +583,8 @@ Where `options` is an optional `Hash` that accepts the following parameters: | ``quantize.fragment`` | Defines behavior for URL fragments. Removes fragments by default. May be `:show` to show URL fragments. Option must be nested inside the `quantize` option. | ``nil`` | | ``application`` | Your Rack application. Necessary for enabling middleware resource names. | ``nil`` | | ``tracer`` | A ``Datadog::Tracer`` instance used to instrument the application. Usually you don't need to set that. | ``Datadog.tracer`` | +| ``request_queuing`` | Track HTTP request time spent in the queue of the frontend server. See [HTTP request queuing](#http-request-queuing) for setup details. Set to `true` to enable. | ``false`` | +| ``web_service_name`` | Service name for frontend server request queuing spans. (e.g. `'nginx'`) | ``'web-server'`` | **Configuring URL quantization behavior** @@ -948,6 +951,30 @@ end Distributed tracing is disabled by default. +### HTTP request queuing + +Traces that originate from HTTP requests can be configured to include the time spent in a frontend web server or load balancer queue, before the request reaches the Ruby application. + +This functionality is **experimental** and deactivated by default. + +To activate this feature, you must add a ``X-Request-Start`` or ``X-Queue-Start`` header from your web server (i.e. Nginx). The following is an Nginx configuration example: + +``` +# /etc/nginx/conf.d/ruby_service.conf +server { + listen 8080; + + location / { + proxy_set_header X-Request-Start "t=${msec}"; + proxy_pass http://web:3000; + } +} +``` + +Then you must enable the request queuing feature in the integration handling the request. + +For Rack based applications, see the [documentation](#rack) for details for enabling this feature. + ### Processing Pipeline Some applications might require that traces be altered or filtered out before they are sent upstream. The processing pipeline allows users to create *processors* to define such behavior. diff --git a/lib/ddtrace/contrib/rack/middlewares.rb b/lib/ddtrace/contrib/rack/middlewares.rb index d071072c9e9..0be19b2841e 100644 --- a/lib/ddtrace/contrib/rack/middlewares.rb +++ b/lib/ddtrace/contrib/rack/middlewares.rb @@ -1,6 +1,7 @@ require 'ddtrace/ext/app_types' require 'ddtrace/ext/http' require 'ddtrace/propagation/http_propagator' +require 'ddtrace/contrib/rack/request_queue' module Datadog module Contrib @@ -19,10 +20,28 @@ def initialize(app) @app = app end + def compute_queue_time(env, tracer) + return unless Datadog.configuration[:rack][:request_queuing] + + # parse the request queue time + request_start = Datadog::Contrib::Rack::QueueTime.get_request_start(env) + return if request_start.nil? + + tracer.trace( + 'http_server.queue', + start_time: request_start, + service: Datadog.configuration[:rack][:web_service_name] + ) + end + def call(env) # retrieve integration settings tracer = Datadog.configuration[:rack][:tracer] + # [experimental] create a root Span to keep track of frontend web servers + # (i.e. Apache, nginx) if the header is properly set + frontend_span = compute_queue_time(env, tracer) + trace_options = { service: Datadog.configuration[:rack][:service_name], resource: nil, @@ -77,6 +96,7 @@ def call(env) # ensure the request_span is finished and the context reset; # this assumes that the Rack middleware creates a root span request_span.finish + frontend_span.finish unless frontend_span.nil? # TODO: Remove this once we change how context propagation works. This # ensures we clean thread-local variables on each HTTP request avoiding diff --git a/lib/ddtrace/contrib/rack/patcher.rb b/lib/ddtrace/contrib/rack/patcher.rb index 50649916be1..5ffbaedcf3e 100644 --- a/lib/ddtrace/contrib/rack/patcher.rb +++ b/lib/ddtrace/contrib/rack/patcher.rb @@ -14,6 +14,13 @@ module Patcher get_option(:tracer).set_service_info(value, 'rack', Ext::AppTypes::WEB) value end + option :request_queuing, default: false + option :web_service_name, default: 'web-server', depends_on: [:tracer, :request_queuing] do |value| + if get_option(:request_queuing) + get_option(:tracer).set_service_info(value, 'webserver', Ext::AppTypes::WEB) + end + value + end module_function diff --git a/lib/ddtrace/contrib/rack/request_queue.rb b/lib/ddtrace/contrib/rack/request_queue.rb new file mode 100644 index 00000000000..4eb97be5a89 --- /dev/null +++ b/lib/ddtrace/contrib/rack/request_queue.rb @@ -0,0 +1,34 @@ +module Datadog + module Contrib + module Rack + # QueueTime simply... + module QueueTime + REQUEST_START = 'HTTP_X_REQUEST_START'.freeze + QUEUE_START = 'HTTP_X_QUEUE_START'.freeze + + module_function + + def get_request_start(env, now = Time.now.utc) + header = env[REQUEST_START] || env[QUEUE_START] + return unless header + + # nginx header is in the format "t=1512379167.574" + # TODO: this should be generic enough to work with any + # frontend web server or load balancer + time_string = header.split('t=')[1] + return if time_string.nil? + + # return the request_start only if it's lesser than + # current time, to avoid significant clock skew + request_start = Time.at(time_string.to_f) + request_start.utc > now ? nil : request_start + rescue StandardError => e + # in case of an Exception we don't create a + # `request.queuing` span + Datadog::Tracer.log.debug("[rack] unable to parse request queue headers: #{e}") + nil + end + end + end + end +end diff --git a/test/contrib/rack/request_parser_test.rb b/test/contrib/rack/request_parser_test.rb new file mode 100644 index 00000000000..d1a90a66b96 --- /dev/null +++ b/test/contrib/rack/request_parser_test.rb @@ -0,0 +1,13 @@ +require 'ddtrace/contrib/rack/request_queue' + +class QueueTimeParserTest < Minitest::Test + include Rack::Test::Methods + + def test_nginx_header + # ensure nginx headers are properly parsed + headers = {} + headers['HTTP_X_REQUEST_START'] = 't=1512379167.574' + request_start = Datadog::Contrib::Rack::QueueTime.get_request_start(headers) + assert_equal(1512379167.574, request_start.to_f) + end +end diff --git a/test/contrib/rack/request_queuing_test.rb b/test/contrib/rack/request_queuing_test.rb new file mode 100644 index 00000000000..f77c89db154 --- /dev/null +++ b/test/contrib/rack/request_queuing_test.rb @@ -0,0 +1,124 @@ +require 'contrib/rack/helpers' + +class RequestQueuingTest < RackBaseTest + def setup + super + # enable request_queuing + Datadog.configuration[:rack][:request_queuing] = true + end + + def test_request_queuing_header + # ensure a queuing Span is created if the header is available + request_start = (Time.now.utc - 5).to_i + header 'x-request-start', "t=#{request_start}" + get '/success/' + assert last_response.ok? + + spans = @tracer.writer.spans + assert_equal(2, spans.length) + + rack_span = spans.find { |s| s.name == 'rack.request' } + frontend_span = spans.find { |s| s.name == 'http_server.queue' } + refute_nil(rack_span) + refute_nil(frontend_span) + + assert_equal('http', rack_span.span_type) + assert_equal('rack', rack_span.service) + assert_equal('GET 200', rack_span.resource) + assert_equal('GET', rack_span.get_tag('http.method')) + assert_equal('200', rack_span.get_tag('http.status_code')) + assert_equal('/success/', rack_span.get_tag('http.url')) + assert_equal(0, rack_span.status) + assert_equal(frontend_span.span_id, rack_span.parent_id) + + assert_equal('web-server', frontend_span.service) + assert_equal(request_start, frontend_span.start_time.to_i) + end + + def test_request_alternative_queuing_header + # ensure a queuing Span is created if the header is available + request_start = (Time.now.utc - 5).to_i + header 'x-queue-start', "t=#{request_start}" + get '/success/' + assert last_response.ok? + + spans = @tracer.writer.spans + assert_equal(2, spans.length) + + rack_span = spans.find { |s| s.name == 'rack.request' } + frontend_span = spans.find { |s| s.name == 'http_server.queue' } + refute_nil(rack_span) + refute_nil(frontend_span) + + assert_equal('http', rack_span.span_type) + assert_equal('rack', rack_span.service) + assert_equal('GET 200', rack_span.resource) + assert_equal('GET', rack_span.get_tag('http.method')) + assert_equal('200', rack_span.get_tag('http.status_code')) + assert_equal('/success/', rack_span.get_tag('http.url')) + assert_equal(0, rack_span.status) + assert_equal(frontend_span.span_id, rack_span.parent_id) + + assert_equal('web-server', frontend_span.service) + assert_equal(request_start, frontend_span.start_time.to_i) + end + + def test_request_queuing_service_name + # ensure a queuing Span is created if the header is available + Datadog.configuration[:rack][:web_service_name] = 'nginx' + request_start = (Time.now.utc - 5).to_i + header 'x-request-start', "t=#{request_start}" + get '/success/' + assert last_response.ok? + + spans = @tracer.writer.spans + assert_equal(2, spans.length) + + rack_span = spans.find { |s| s.name == 'rack.request' } + frontend_span = spans.find { |s| s.name == 'http_server.queue' } + refute_nil(rack_span) + refute_nil(frontend_span) + + assert_equal('nginx', frontend_span.service) + end + + def test_clock_skew + # ensure a queuing Span is NOT created if there is a clock skew + # where the starting time is greater than current host Time.now + request_start = (Time.now.utc + 5).to_i + header 'x-request-start', "t=#{request_start}" + get '/success/' + assert last_response.ok? + + spans = @tracer.writer.spans + assert_equal(1, spans.length) + + rack_span = spans[0] + assert_equal('rack.request', rack_span.name) + end + + def test_wrong_header + # ensure a queuing Span is NOT created if the header is wrong + header 'x-request-start', 'something_weird' + get '/success/' + assert last_response.ok? + + spans = @tracer.writer.spans + assert_equal(1, spans.length) + + rack_span = spans[0] + assert_equal('rack.request', rack_span.name) + end + + def test_enabled_missing_header + # ensure a queuing Span is NOT created if the header is missing + get '/success/' + assert last_response.ok? + + spans = @tracer.writer.spans + assert_equal(1, spans.length) + + rack_span = spans[0] + assert_equal('rack.request', rack_span.name) + end +end