Track method call times/counts as a single metric

Previously we'd create a separate Metric instance for every method call
that would exceed the method call threshold. This is problematic because
it doesn't provide us with information to accurately get the _total_
execution time of a particular method. For example, if the method
"Foo#bar" was called 4 times with a runtime of ~10 milliseconds we'd end
up with 4 different Metric instances. If we were to then get the
average/95th percentile/etc of the timings this would be roughly 10
milliseconds. However, the _actual_ total time spent in this method
would be around 40 milliseconds.

To solve this problem we now create a single Metric instance per method.
This Metric instance contains the _total_ real/CPU time and the call
count for every instrumented method.

3 files changed, 111 insertions, 6 deletions

diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb
index cdf641341cb..8809b7e3f12 100644
--- a/spec/lib/gitlab/metrics/instrumentation_spec.rb
+++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb
@@ -78,9 +78,8 @@ describe Gitlab::Metrics::Instrumentation do
         allow(described_class).to receive(:transaction).
           and_return(transaction)
 
-        expect(transaction).to receive(:add_metric).
-          with(described_class::SERIES, hash_including(:duration, :cpu_duration),
-               method: 'Dummy.foo')
+        expect(transaction).to receive(:measure_method).
+          with('Dummy.foo')
 
         @dummy.foo
       end
@@ -158,9 +157,8 @@ describe Gitlab::Metrics::Instrumentation do
         allow(described_class).to receive(:transaction).
           and_return(transaction)
 
-        expect(transaction).to receive(:add_metric).
-          with(described_class::SERIES, hash_including(:duration, :cpu_duration),
-               method: 'Dummy#bar')
+        expect(transaction).to receive(:measure_method).
+          with('Dummy#bar')
 
         @dummy.new.bar
       end
diff --git a/spec/lib/gitlab/metrics/method_call_spec.rb b/spec/lib/gitlab/metrics/method_call_spec.rb
new file mode 100644
index 00000000000..8d05081eecb
--- /dev/null
+++ b/spec/lib/gitlab/metrics/method_call_spec.rb
@@ -0,0 +1,91 @@
+require 'spec_helper'
+
+describe Gitlab::Metrics::MethodCall do
+  let(:method_call) { described_class.new('Foo#bar', 'foo') }
+
+  describe '#measure' do
+    it 'measures the performance of the supplied block' do
+      method_call.measure { 'foo' }
+
+      expect(method_call.real_time).to be_a_kind_of(Numeric)
+      expect(method_call.cpu_time).to be_a_kind_of(Numeric)
+      expect(method_call.call_count).to eq(1)
+    end
+  end
+
+  describe '#to_metric' do
+    it 'returns a Metric instance' do
+      method_call.measure { 'foo' }
+      metric = method_call.to_metric
+
+      expect(metric).to be_an_instance_of(Gitlab::Metrics::Metric)
+      expect(metric.series).to eq('foo')
+
+      expect(metric.values[:duration]).to be_a_kind_of(Numeric)
+      expect(metric.values[:cpu_duration]).to be_a_kind_of(Numeric)
+      expect(metric.values[:call_count]).to an_instance_of(Fixnum)
+
+      expect(metric.tags).to eq({ method: 'Foo#bar' })
+    end
+  end
+
+  describe '#above_threshold?' do
+    it 'returns false when the total call time is not above the threshold' do
+      expect(method_call.above_threshold?).to eq(false)
+    end
+
+    it 'returns true when the total call time is above the threshold' do
+      expect(method_call).to receive(:real_time).and_return(9000)
+
+      expect(method_call.above_threshold?).to eq(true)
+    end
+  end
+
+  describe '#call_count' do
+    context 'without any method calls' do
+      it 'returns 0' do
+        expect(method_call.call_count).to eq(0)
+      end
+    end
+
+    context 'with method calls' do
+      it 'returns the number of method calls' do
+        method_call.measure { 'foo' }
+
+        expect(method_call.call_count).to eq(1)
+      end
+    end
+  end
+
+  describe '#cpu_time' do
+    context 'without timings' do
+      it 'returns 0.0' do
+        expect(method_call.cpu_time).to eq(0.0)
+      end
+    end
+
+    context 'with timings' do
+      it 'returns the total CPU time' do
+        method_call.measure { 'foo' }
+
+        expect(method_call.cpu_time >= 0.0).to be(true)
+      end
+    end
+  end
+
+  describe '#real_time' do
+    context 'without timings' do
+      it 'returns 0.0' do
+        expect(method_call.real_time).to eq(0.0)
+      end
+    end
+
+    context 'with timings' do
+      it 'returns the total real time' do
+        method_call.measure { 'foo' }
+
+        expect(method_call.real_time >= 0.0).to be(true)
+      end
+    end
+  end
+end
diff --git a/spec/lib/gitlab/metrics/transaction_spec.rb b/spec/lib/gitlab/metrics/transaction_spec.rb
index 1d5a51a157e..3b1c67a2147 100644
--- a/spec/lib/gitlab/metrics/transaction_spec.rb
+++ b/spec/lib/gitlab/metrics/transaction_spec.rb
@@ -46,6 +46,22 @@ describe Gitlab::Metrics::Transaction do
     end
   end
 
+  describe '#measure_method' do
+    it 'adds a new method if it does not exist already' do
+      transaction.measure_method('Foo#bar') { 'foo' }
+
+      expect(transaction.methods['Foo#bar']).
+        to be_an_instance_of(Gitlab::Metrics::MethodCall)
+    end
+
+    it 'adds timings to an existing method call' do
+      transaction.measure_method('Foo#bar') { 'foo' }
+      transaction.measure_method('Foo#bar') { 'foo' }
+
+      expect(transaction.methods['Foo#bar'].call_count).to eq(2)
+    end
+  end
+
   describe '#increment' do
     it 'increments a counter' do
       transaction.increment(:time, 1)