Collect measure and distribution metrics even on return or exception

CHANGELOG.md

@@ -5,6 +5,29 @@ please at an entry to the "unreleased changes" section below.
 
 ### Unreleased changes
 
+## Version 2.3.3
+
+- Capture measure and distribution metrics on exception and early return (#134)
+
+NOTE: Now that exceptions are measured statistics may behave differently. An exception example:
+```
+StatsD.measure('myhttpcall') do
+  my_http_object.invoke
+end
+```
+Version 2.3.2 and below did not track metrics whenever a HTTP Timeout exception was raised.
+2.3.3 and above will include those metrics which may increase the values included.
+
+A return example:
+```
+StatsD.measure('myexpensivecalculation') do
+  return if expensive_calculation_disabled?
+  expensive_calculation
+end
+```
+If `expensive_calculation_disabled?` is true 50% of the time version 2.3.2 will drop the
+average metric considerably.
+
 ## Version 2.3.2
 
 - Add option to override global prefix for metrics (#148)

lib/statsd/instrument.rb

@@ -58,17 +58,13 @@ def self.generate_metric_name(metric_name, callee, *args)
 
     if Process.respond_to?(:clock_gettime)
       # @private
-      def self.duration
-        start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
-        yield
-        Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
+      def self.current_timestamp
+        Process.clock_gettime(Process::CLOCK_MONOTONIC)
       end
     else
       # @private
-      def self.duration
-        start = Time.now
-        yield
-        Time.now - start
+      def self.current_timestamp
+        Time.now
       end
     end
 
@@ -310,11 +306,16 @@ def measure(key, value = nil, *metric_options, &block)
     value, metric_options = parse_options(value, metric_options)
     type = (!metric_options.empty? && metric_options.first[:as_dist] ? :d : :ms)
 
-    result = nil
-    value  = 1000 * StatsD::Instrument.duration { result = block.call } if block_given?
-    metric = collect_metric(type, key, value, metric_options)
-    result = metric unless block_given?
-    result
+    return collect_metric(type, key, value, metric_options) unless block_given?
+
+    start = StatsD::Instrument.current_timestamp
+    begin
+      block.call
+    ensure
+      # Ensure catches both a raised exception and a return in the invoked block
+      value = 1000 * (StatsD::Instrument.current_timestamp - start)
+      collect_metric(type, key, value, metric_options)
+    end
   end
 
   # Emits a counter metric.
@@ -373,11 +374,16 @@ def histogram(key, value, *metric_options)
   #      end
   def distribution(key, value=nil, *metric_options, &block)
     value, metric_options = parse_options(value, metric_options)
-    result = nil
-    value  = 1000 * StatsD::Instrument.duration { result = block.call } if block_given?
-    metric = collect_metric(:d, key, value, metric_options)
-    result = metric unless block_given?
-    result
+
+    return collect_metric(:d, key, value, metric_options) unless block_given?
+
+    start = StatsD::Instrument.current_timestamp
+    begin
+      block.call
+    ensure
+      value = 1000 * (StatsD::Instrument.current_timestamp - start)
+      collect_metric(:d, key, value, metric_options)
+    end
   end
 
   # Emits a key/value metric.

lib/statsd/instrument/version.rb

@@ -1,5 +1,5 @@
 module StatsD
   module Instrument
-    VERSION = "2.3.2"
+    VERSION = "2.3.3"
   end
 end

test/statsd_test.rb

@@ -46,7 +46,7 @@ def test_statsd_measure_with_explicit_value_and_sample_rate
   end
 
   def test_statsd_measure_with_benchmarked_block_duration
-    StatsD::Instrument.stubs(:duration).returns(1.12)
+    StatsD::Instrument.stubs(:current_timestamp).returns(5.0, 5.0 + 1.12)
     metric = capture_statsd_call do
       StatsD.measure('values.foobar') { 'foo' }
     end
@@ -70,6 +70,40 @@ def test_statsd_measure_returns_return_value_of_block_even_if_nil
     assert_nil return_value
   end
 
+  def test_statsd_measure_with_return_in_block_still_captures
+    StatsD::Instrument.stubs(:current_timestamp).returns(5.0, 6.12)
+    result = nil
+    metric = capture_statsd_call do
+      lambda = -> do
+        StatsD.measure('values.foobar') { return 'from lambda'}
+      end
+
+      result = lambda.call
+    end
+
+    assert_equal 'from lambda', result
+    assert_equal 1120.0, metric.value
+  end
+
+  def test_statsd_measure_with_exception_in_block_still_captures
+    StatsD::Instrument.stubs(:current_timestamp).returns(5.0, 6.12)
+    result = nil
+    metric = capture_statsd_call do
+      lambda = -> do
+        StatsD.measure('values.foobar') { raise 'from lambda'}
+      end
+
+      begin
+        result = lambda.call
+      rescue
+      end
+
+    end
+
+    assert_nil result
+    assert_equal 1120.0, metric.value
+  end
+
   def test_statsd_increment
     result = nil
     metric = capture_statsd_call { result = StatsD.increment('values.foobar', 3) }
@@ -149,16 +183,52 @@ def test_statsd_distribution
   end
 
   def test_statsd_distribution_with_benchmarked_block_duration
-    StatsD::Instrument.stubs(:duration).returns(1.12)
+    StatsD::Instrument.stubs(:current_timestamp).returns(5.0, 5.0 + 1.12)
     metric = capture_statsd_call do
       StatsD.distribution('values.foobar') { 'foo' }
     end
     assert_equal :d, metric.type
     assert_equal 1120.0, metric.value
   end
 
+  def test_statsd_distribution_with_return_in_block_still_captures
+    StatsD::Instrument.stubs(:current_timestamp).returns(5.0, 5.0 + 1.12)
+    result = nil
+    metric = capture_statsd_call do
+      lambda = -> do
+        StatsD.distribution('values.foobar') { return 'from lambda'}
+      end
+
+      result = lambda.call
+    end
+
+    assert_equal 'from lambda', result
+    assert_equal :d, metric.type
+    assert_equal 1120.0, metric.value
+  end
+
+  def test_statsd_distribution_with_exception_in_block_still_captures
+    StatsD::Instrument.stubs(:current_timestamp).returns(5.0, 5.0 + 1.12)
+    result = nil
+    metric = capture_statsd_call do
+      lambda = -> do
+        StatsD.distribution('values.foobar') { raise 'from lambda'}
+      end
+
+      begin
+        result = lambda.call
+      rescue
+      end
+
+    end
+
+    assert_nil result
+    assert_equal :d, metric.type
+    assert_equal 1120.0, metric.value
+  end
+
   def test_statsd_distribution_with_block_and_options
-    StatsD::Instrument.stubs(:duration).returns(1.12)
+    StatsD::Instrument.stubs(:current_timestamp).returns(5.0, 5.0 + 1.12)
     metric = capture_statsd_call do
       StatsD.distribution('values.foobar', :tags => ['test'], :sample_rate => 0.9) { 'foo' }
     end