diff --git a/lib/new_relic/agent/instrumentation/queue_time.rb b/lib/new_relic/agent/instrumentation/queue_time.rb new file mode 100644 index 0000000000..68d5877516 --- /dev/null +++ b/lib/new_relic/agent/instrumentation/queue_time.rb @@ -0,0 +1,91 @@ +module NewRelic + module Agent + module Instrumentation + module QueueTime + MAIN_HEADER = 'X_REQUEST_START' + + HEADER_REGEX = /([^\s\/,(t=)]+)? ?t=([0-9]+)/ + SERVER_METRIC = 'WebFrontend/WebServer/' + ALL_METRIC = 'WebFrontend/WebServer/all' + + # main method to extract queue time info from env hash, + # records individual server metrics and one roll-up for all servers + def parse_queue_time_from(env) + start_time = Time.now + matches = env[MAIN_HEADER].to_s.scan(HEADER_REGEX).map do |name, time| + [name, convert_from_microseconds(time.to_i)] + end + record_individual_server_stats(start_time, matches) + record_rollup_stat(start_time, matches) + end + + private + + # goes through the list of servers and records each one in + # reverse order, subtracting the time for each successive + # server from the earlier ones in the list. + # an example because it's complicated: + # start data: + # [['a', Time.at(1000)], ['b', Time.at(1001)]], start time: Time.at(1002) + # initial run: Time.at(1002), ['b', Time.at(1001)] + # next: Time.at(1001), ['a', Time.at(1000)] + # see tests for more + def record_individual_server_stats(end_time, matches) # (Time, [[String, Time]]) -> nil + matches = matches.sort_by {|name, time| time } + matches.reverse! + matches.inject(end_time) {|start_time, pair| + name, time = pair + record_queue_time_for(name, time, start_time) + time + } + end + + # records the total time for all servers in a rollup metric + def record_rollup_stat(start_time, matches) # (Time, [String, Time]) -> nil + # default to the start time if we have no header + oldest_time = find_oldest_time(matches) || start_time + record_time_stat(ALL_METRIC, oldest_time, start_time) + end + + # searches for the first server to touch a request + def find_oldest_time(matches) # [[String, Time]] -> Time + matches.map do |name, time| + time + end.min + end + + # basically just assembles the metric name + def record_queue_time_for(name, time, start_time) # (Maybe String, Time, Time) -> nil + record_time_stat(SERVER_METRIC + name, time, start_time) if name + end + + # Checks that the time is not negative, and does the actual + # data recording + def record_time_stat(name, start_time, end_time) # (String, Time, Time) -> nil + total_time = end_time - start_time + if total_time < 0 + raise 'should not provide an end time less than start time' + else + NewRelic::Agent.get_stats(name).trace_call(total_time) + end + end + + # convert a time to the value provided by the header, for convenience + def convert_to_microseconds(time) # Time -> Int + raise TypeError.new('Cannot convert a non-time into microseconds') unless time.is_a?(Time) || time.is_a?(Numeric) + return time if time.is_a?(Numeric) + (time.to_f * 1000000).to_i + end + + # convert a time from the header value (time in microseconds) + # into a ruby time object + def convert_from_microseconds(int) # Int -> Time + raise TypeError.new('Cannot convert a non-number into a time') unless int.is_a?(Time) || int.is_a?(Numeric) + return int if int.is_a?(Time) + Time.at((int.to_f / 1000000)) + end + end + end + end +end + diff --git a/test/new_relic/agent/queue_time_test.rb b/test/new_relic/agent/queue_time_test.rb new file mode 100644 index 0000000000..d1a6fda4ff --- /dev/null +++ b/test/new_relic/agent/queue_time_test.rb @@ -0,0 +1,117 @@ +require File.expand_path(File.join(File.dirname(__FILE__), '..', '..', 'test_helper')) +class QueueTimeTest < Test::Unit::TestCase + require 'new_relic/agent/instrumentation/queue_time' + include NewRelic::Agent::Instrumentation::QueueTime + + def setup + NewRelic::Agent.instance.stats_engine.clear_stats + end + + # test helper method + def check_metric(metric, value, delta) + time = NewRelic::Agent.get_stats(metric).total_call_time + assert_between (value - delta), (value + delta), time, "Metric #{metric} not in expected range: was #{time} but expected in #{value - delta} to #{value + delta}!" + end + + # initial base case, a router and a static content server + def test_parse_queue_time_from_initial + env = {} + time1 = ((Time.now - 2).to_f * 1_000_000.0).to_i + time2 = ((Time.now - 1).to_f * 1_000_000.0).to_i + env['X_REQUEST_START'] = "servera t=#{time1}, serverb t=#{time2}" + assert_calls_metrics('WebFrontend/WebServer/all', 'WebFrontend/WebServer/servera', 'WebFrontend/WebServer/serverb') do + parse_queue_time_from(env) + end + check_metric('WebFrontend/WebServer/all', 2.0, 0.1) + check_metric('WebFrontend/WebServer/servera', 1.0, 0.1) + check_metric('WebFrontend/WebServer/serverb', 1.0, 0.1) + end + + # test for backwards compatibility with old header + def test_parse_queue_time_from_with_no_server_name + assert_calls_metrics('WebFrontend/WebServer/all') do + parse_queue_time_from({'X_REQUEST_START' => "t=#{convert_to_microseconds(Time.now) - 1000000}"}) + end + check_metric('WebFrontend/WebServer/all', 1.0, 0.1) + end + + def test_parse_queue_time_from_with_no_header + assert_calls_metrics('WebFrontend/WebServer/all') do + parse_queue_time_from({}) + end + end + + # each server should be one second, and the total would be 2 seconds + def test_record_individual_server_stats + matches = [['foo', Time.at(1000)], ['bar', Time.at(1001)]] + assert_calls_metrics('WebFrontend/WebServer/foo', 'WebFrontend/WebServer/bar') do + record_individual_server_stats(Time.at(1002), matches) + end + check_metric('WebFrontend/WebServer/foo', 1.0, 0.1) + check_metric('WebFrontend/WebServer/bar', 1.0, 0.1) + end + + def test_record_rollup_stat + assert_calls_metrics('WebFrontend/WebServer/all') do + record_rollup_stat(Time.at(1001), [['a', Time.at(1000)]]) + end + check_metric('WebFrontend/WebServer/all', 1.0, 0.1) + end + + def test_record_rollup_stat_no_data + assert_calls_metrics('WebFrontend/WebServer/all') do + record_rollup_stat(Time.at(1001), []) + end + check_metric('WebFrontend/WebServer/all', 0.0, 0.001) + end + + # check all the combinations to make sure that ordering doesn't + # affect the return value + def test_find_oldest_time + test_arrays = [ + ['a', Time.at(1000)], + ['b', Time.at(1001)], + ['c', Time.at(1002)], + ['d', Time.at(1000)], + ] + test_arrays = test_arrays.permutation + test_arrays.each do |test_array| + assert_equal find_oldest_time(test_array), Time.at(1000), "Should be the oldest time in the array" + end + end + + # trivial test but the method doesn't do much + def test_record_queue_time_for + name = 'foo' + time = Time.at(1000) + start_time = Time.at(1001) + self.expects(:record_time_stat).with('WebFrontend/WebServer/foo', time, start_time) + record_queue_time_for(name, time, start_time) + end + + def test_record_time_stat + assert_calls_metrics('WebFrontend/WebServer/foo') do + record_time_stat('WebFrontend/WebServer/foo', Time.at(1000), Time.at(1001)) + end + check_metric('WebFrontend/WebServer/foo', 1.0, 0.1) + assert_raises(RuntimeError) do + record_time_stat('foo', Time.at(1001), Time.at(1000)) + end + end + + def test_convert_to_microseconds + assert_equal((1_000_000_000), convert_to_microseconds(Time.at(1000)), 'time at 1000 seconds past epoch should be 1,000,000,000 usec') + assert_equal 1_000_000_000, convert_to_microseconds(1_000_000_000), 'should not mess with a number if passed in' + assert_raises(TypeError) do + convert_to_microseconds('whoo yeah buddy') + end + end + + def test_convert_from_microseconds + assert_equal Time.at(1000), convert_from_microseconds(1_000_000_000), 'time at 1,000,000,000 usec should be 1000 seconds after epoch' + assert_equal Time.at(1000), convert_from_microseconds(Time.at(1000)), 'should not mess with a time passed in' + assert_raises(TypeError) do + convert_from_microseconds('10000000000') + end + end +end diff --git a/test/test_helper.rb b/test/test_helper.rb index b140f8e3dd..8828274c67 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -1,8 +1,7 @@ module NewRelic; TEST = true; end unless defined? NewRelic::TEST ENV['RAILS_ENV'] = 'test' NEWRELIC_PLUGIN_DIR = File.expand_path(File.join(File.dirname(__FILE__),"..")) -$LOAD_PATH << '.' -$LOAD_PATH << '../../..' +$LOAD_PATH << File.join(NEWRELIC_PLUGIN_DIR,"lib") $LOAD_PATH << File.join(NEWRELIC_PLUGIN_DIR,"test") $LOAD_PATH << File.join(NEWRELIC_PLUGIN_DIR,"ui/helpers") $LOAD_PATH << File.expand_path('.') @@ -34,6 +33,20 @@ def assert_between(floor, ceiling, value, message = nil) message || "expected #{floor} <= #{value} <= #{ceiling}" end +def generate_metric_counts(*metrics) + metrics.inject({}) do |sum, metric| + sum[metric] = NewRelic::Agent.get_stats(metric).call_count + sum + end +end + +def assert_calls_metrics(*metrics) + first_metrics = generate_metric_counts(*metrics) + yield + last_metrics = generate_metric_counts(*metrics) + assert_not_equal first_metrics, last_metrics, "should have changed these metrics" +end + def compare_metrics expected_list, actual_list actual = Set.new actual_list actual.delete('GC/cumulative') # in case we are in REE