Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP
Browse files

RUBY-1024 Handle negative queue times caused by clock drift or miscon…

…figuration

Conflicts:
	test/new_relic/agent/instrumentation/controller_instrumentation_test.rb
  • Loading branch information...
commit 6cee6b5afb8e6ab228491ad3d83e2ba9f2104326 1 parent 28cde2e
Ben Weintraub benweint authored
2  lib/new_relic/agent/instrumentation/controller_instrumentation.rb
View
@@ -462,7 +462,7 @@ def _record_queue_length
# for the start time is found.
def _detect_upstream_wait(now)
if newrelic_request_headers
- queue_start = QueueTime.parse_frontend_timestamp(newrelic_request_headers)
+ queue_start = QueueTime.parse_frontend_timestamp(newrelic_request_headers, now)
QueueTime.record_frontend_metrics(queue_start, now) if queue_start
end
queue_start || now
11 lib/new_relic/agent/instrumentation/queue_time.rb
View
@@ -18,14 +18,21 @@ module QueueTime
module_function
- def parse_frontend_timestamp(headers)
+ def parse_frontend_timestamp(headers, now=Time.now)
candidate_headers = [ REQUEST_START_HEADER, QUEUE_START_HEADER,
MIDDLEWARE_START_HEADER ]
- candidate_headers.map do |header|
+ earliest = candidate_headers.map do |header|
if headers[header]
parse_timestamp(timestamp_string_from_header_value(headers[header]))
end
end.compact.min
+
+ if earliest && earliest > now
+ NewRelic::Agent.logger.debug("Negative queue time detected, treating as zero: start=#{earliest.to_f} > now=#{now.to_f}")
+ earliest = now
+ end
+
+ earliest
end
def record_frontend_metrics(start_time, now=Time.now)
8 test/new_relic/agent/instrumentation/controller_instrumentation_test.rb
View
@@ -14,7 +14,7 @@ def test_detect_upstream_wait_basic
# should return the start time above by default
@object.expects(:newrelic_request_headers).returns({:request => 'headers'}).twice
NewRelic::Agent::Instrumentation::QueueTime.expects(:parse_frontend_timestamp) \
- .with({:request => 'headers'}).returns(start_time)
+ .with({:request => 'headers'}, start_time).returns(start_time)
assert_equal(start_time, @object.send(:_detect_upstream_wait, start_time))
end
@@ -23,17 +23,17 @@ def test_detect_upstream_wait_with_upstream
runs_at = start_time + 1
@object = TestObject.new
@object.expects(:newrelic_request_headers).returns(true).twice
- NewRelic::Agent::Instrumentation::QueueTime.expects(:parse_frontend_timestamp).returns(start_time)
+ NewRelic::Agent::Instrumentation::QueueTime.expects(:parse_frontend_timestamp) \
+ .with(true, runs_at).returns(start_time)
assert_equal(start_time, @object.send(:_detect_upstream_wait, runs_at))
end
def test_detect_upstream_wait_swallows_errors
start_time = Time.now
- @object = TestObject.new
# should return the start time above when an error is raised
@object.expects(:newrelic_request_headers).returns({:request => 'headers'}).twice
NewRelic::Agent::Instrumentation::QueueTime.expects(:parse_frontend_timestamp) \
- .with({:request => 'headers'}).raises("an error")
+ .with({:request => 'headers'}, start_time).raises("an error")
assert_equal(start_time, @object.send(:_detect_upstream_wait, start_time))
end
7 test/new_relic/agent/instrumentation/queue_time_test.rb
View
@@ -54,6 +54,13 @@ def test_parse_frontend_timestamp_from_header_missing_t_equals
assert_in_delta(seconds_ago(60), QueueTime.parse_frontend_timestamp(header), 0.1)
end
+ def test_parse_frontend_timestamp_from_header_negative
+ now = Time.now
+ the_future = Time.at(now.to_f + 60)
+ header = { 'HTTP_X_REQUEST_START' => the_future.to_f.to_s }
+ assert_in_delta(now, QueueTime.parse_frontend_timestamp(header, now), 0.1)
+ end
+
def test_recording_queue_time_metric
assert_metric_value_in_delta(60, 'WebFrontend/QueueTime', 0.1) do
QueueTime.record_frontend_metrics(Time.at(Time.now.to_f - 60))
Please sign in to comment.
Something went wrong with that request. Please try again.