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.

CHANGELOG

@@ -36,6 +36,7 @@ v 8.9.0 (unreleased)
   - Added shortcut 'y' for copying a files content hash URL #14470
   - Fix groups API to list only user's accessible projects
   - Fix horizontal scrollbar for long commit message.
+  - GitLab Performance Monitoring now tracks the total method execution time and call count per method
   - Add Environments and Deployments
   - Redesign account and email confirmation emails
   - Don't fail builds for projects that are deleted

doc/development/instrumentation.md

@@ -94,23 +94,8 @@ Visibility: public
 Number of lines: 21
 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

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

lib/gitlab/metrics/method_call.rb

+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

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("#{prefix}#{series}", values, tags)
+        @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
+        @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

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

spec/lib/gitlab/metrics/method_call_spec.rb

+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

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)