queue time, initial header work

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
+

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

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