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, 84 insertions, 22 deletions

diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb
index d81d26754fe..dcec7543c13 100644
--- a/lib/gitlab/metrics/instrumentation.rb
+++ b/lib/gitlab/metrics/instrumentation.rb
@@ -148,23 +148,8 @@ module Gitlab
 
         proxy_module.class_eval <<-EOF, __FILE__, __LINE__ + 1
           def #{name}(#{args_signature})
-            trans = Gitlab::Metrics::Instrumentation.transaction
-
-            if trans
-              start     = Time.now
-              cpu_start = Gitlab::Metrics::System.cpu_time
-              retval    = super
-              duration  = (Time.now - start) * 1000.0
-
-              if duration >= Gitlab::Metrics.method_call_threshold
-                cpu_duration = Gitlab::Metrics::System.cpu_time - cpu_start
-
-                trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES,
-                                 { duration: duration, cpu_duration: cpu_duration },
-                                 method: #{label.inspect})
-              end
-
-              retval
+            if trans = Gitlab::Metrics::Instrumentation.transaction
+              trans.measure_method(#{label.inspect}) { super }
             else
               super
             end
diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb
new file mode 100644
index 00000000000..faf0d9b6318
--- /dev/null
+++ b/lib/gitlab/metrics/method_call.rb
@@ -0,0 +1,52 @@
+module Gitlab
+  module Metrics
+    # Class for tracking timing information about method calls
+    class MethodCall
+      attr_reader :real_time, :cpu_time, :call_count
+
+      # name - The full name of the method (including namespace) such as
+      #        `User#sign_in`.
+      #
+      # series - The series to use for storing the data.
+      def initialize(name, series)
+        @name = name
+        @series = series
+        @real_time = 0.0
+        @cpu_time = 0.0
+        @call_count = 0
+      end
+
+      # Measures the real and CPU execution time of the supplied block.
+      def measure
+        start_real = Time.now
+        start_cpu = System.cpu_time
+        retval = yield
+
+        @real_time += (Time.now - start_real) * 1000.0
+        @cpu_time += System.cpu_time.to_f - start_cpu
+        @call_count += 1
+
+        retval
+      end
+
+      # Returns a Metric instance of the current method call.
+      def to_metric
+        Metric.new(
+          @series,
+          {
+            duration:     real_time,
+            cpu_duration: cpu_time,
+            call_count:   call_count
+          },
+          method: @name
+        )
+      end
+
+      # Returns true if the total runtime of this method exceeds the method call
+      # threshold.
+      def above_threshold?
+        real_time >= Metrics.method_call_threshold
+      end
+    end
+  end
+end
diff --git a/lib/gitlab/metrics/transaction.rb b/lib/gitlab/metrics/transaction.rb
index 2578ddc49f4..4bc5081aa03 100644
--- a/lib/gitlab/metrics/transaction.rb
+++ b/lib/gitlab/metrics/transaction.rb
@@ -4,7 +4,7 @@ module Gitlab
     class Transaction
       THREAD_KEY = :_gitlab_metrics_transaction
 
-      attr_reader :tags, :values
+      attr_reader :tags, :values, :methods
 
       attr_accessor :action
 
@@ -16,6 +16,7 @@ module Gitlab
       #          plus method name.
       def initialize(action = nil)
         @metrics = []
+        @methods = {}
 
         @started_at  = nil
         @finished_at = nil
@@ -51,9 +52,23 @@ module Gitlab
       end
 
       def add_metric(series, values, tags = {})
-        prefix = sidekiq? ? 'sidekiq_' : 'rails_'
+        @metrics << Metric.new("#{series_prefix}#{series}", values, tags)
+      end
+
+      # Measures the time it takes to execute a method.
+      #
+      # Multiple calls to the same method add up to the total runtime of the
+      # method.
+      #
+      # name - The full name of the method to measure (e.g. `User#sign_in`).
+      def measure_method(name, &block)
+        unless @methods[name]
+          series = "#{series_prefix}#{Instrumentation::SERIES}"
+
+          @methods[name] = MethodCall.new(name, series)
+        end
 
-        @metrics << Metric.new("#{prefix}#{series}", values, tags)
+        @methods[name].measure(&block)
       end
 
       def increment(name, value)
@@ -84,7 +99,13 @@ module Gitlab
       end
 
       def submit
-        metrics = @metrics.map do |metric|
+        submit = @metrics.dup
+
+        @methods.each do |name, method|
+          submit << method.to_metric if method.above_threshold?
+        end
+
+        submit_hashes = submit.map do |metric|
           hash = metric.to_hash
 
           hash[:tags][:action] ||= @action if @action
@@ -92,12 +113,16 @@ module Gitlab
           hash
         end
 
-        Metrics.submit_metrics(metrics)
+        Metrics.submit_metrics(submit_hashes)
       end
 
       def sidekiq?
         Sidekiq.server?
       end
+
+      def series_prefix
+        sidekiq? ? 'sidekiq_' : 'rails_'
+      end
     end
   end
 end