Reduce instrumentation overhead

This reduces the overhead of the method instrumentation code primarily
by reducing the number of method calls. There are also some other small
optimisations such as not casting timing values to Floats (there's no
particular need for this), using Symbols for method call metric names,
and reducing the number of Hash lookups for instrumented methods.

The exact impact depends on the code being executed. For example, for a
method that's only called once the difference won't be very noticeable.
However, for methods that are called many times the difference can be
more significant.

For example, the loading time of a large commit
(nrclark/dummy_project@81ebdea5df)
was reduced from around 19 seconds to around 15 seconds using these
changes.

CHANGELOG

@@ -15,6 +15,7 @@ v 8.11.0 (unreleased)
   - Add build event color in HipChat messages (David Eisner)
   - Make fork counter always clickable. !5463 (winniehell)
   - All created issues, API or WebUI, can be submitted to Akismet for spam check !5333
+  - The overhead of instrumented method calls has been reduced
   - Remove `search_id` of labels dropdown filter to fix 'Missleading URI for labels in Merge Requests and Issues view'. !5368 (Scott Le)
   - Load project invited groups and members eagerly in `ProjectTeam#fetch_members`
   - Make branches sortable without push permission !5462 (winniehell)

lib/gitlab/metrics.rb

@@ -124,6 +124,11 @@ module Gitlab
       trans.action = action if trans
     end
 
+    # Returns the prefix to use for the name of a series.
+    def self.series_prefix
+      @series_prefix ||= Sidekiq.server? ? 'sidekiq_' : 'rails_'
+    end
+
     # When enabled this should be set before being used as the usual pattern
     # "@foo ||= bar" is _not_ thread-safe.
     if enabled?

lib/gitlab/metrics/instrumentation.rb

@@ -9,14 +9,17 @@ module Gitlab
     #
     #     Gitlab::Metrics::Instrumentation.instrument_method(User, :by_login)
     module Instrumentation
-      SERIES = 'method_calls'
-
       PROXY_IVAR = :@__gitlab_instrumentation_proxy
 
       def self.configure
         yield self
       end
 
+      # Returns the name of the series to use for storing method calls.
+      def self.series
+        @series ||= "#{Metrics.series_prefix}method_calls"
+      end
+
       # Instruments a class method.
       #
       # mod  - The module to instrument as a Module/Class.
@@ -141,15 +144,15 @@ module Gitlab
         # generated method _only_ accepts regular arguments if the underlying
         # method also accepts them.
         if method.arity == 0
-          args_signature = '&block'
+          args_signature = ''
         else
-          args_signature = '*args, &block'
+          args_signature = '*args'
         end
 
         proxy_module.class_eval <<-EOF, __FILE__, __LINE__ + 1
           def #{name}(#{args_signature})
             if trans = Gitlab::Metrics::Instrumentation.transaction
-              trans.measure_method(#{label.inspect}) { super }
+              trans.method_call_for(#{label.to_sym.inspect}).measure { super }
             else
               super
             end

lib/gitlab/metrics/method_call.rb

@@ -11,8 +11,8 @@ module Gitlab
       def initialize(name, series)
         @name = name
         @series = series
-        @real_time = 0.0
-        @cpu_time = 0.0
+        @real_time = 0
+        @cpu_time = 0
         @call_count = 0
       end
 

lib/gitlab/metrics/system.rb

@@ -35,12 +35,12 @@ module Gitlab
       if Process.const_defined?(:CLOCK_THREAD_CPUTIME_ID)
         def self.cpu_time
           Process.
-            clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond).to_f
+            clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond)
         end
       else
         def self.cpu_time
           Process.
-            clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond).to_f
+            clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond)
         end
       end
 
@@ -48,14 +48,14 @@ module Gitlab
       #
       # Returns the time as a Float.
       def self.real_time(precision = :millisecond)
-        Process.clock_gettime(Process::CLOCK_REALTIME, precision).to_f
+        Process.clock_gettime(Process::CLOCK_REALTIME, precision)
       end
 
       # Returns the current monotonic clock time in a given precision.
       #
       # Returns the time as a Float.
       def self.monotonic_time(precision = :millisecond)
-        Process.clock_gettime(Process::CLOCK_MONOTONIC, precision).to_f
+        Process.clock_gettime(Process::CLOCK_MONOTONIC, precision)
       end
     end
   end

lib/gitlab/metrics/transaction.rb

@@ -52,23 +52,16 @@ module Gitlab
       end
 
       def add_metric(series, values, tags = {})
-        @metrics << Metric.new("#{series_prefix}#{series}", values, tags)
+        @metrics << Metric.new("#{Metrics.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)
+      # Returns a MethodCall object for the given name.
+      def method_call_for(name)
+        unless method = @methods[name]
+          @methods[name] = method = MethodCall.new(name, Instrumentation.series)
         end
 
-        @methods[name].measure(&block)
+        method
       end
 
       def increment(name, value)
@@ -115,14 +108,6 @@ module Gitlab
 
         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

@@ -39,6 +39,12 @@ describe Gitlab::Metrics::Instrumentation do
     allow(@dummy).to receive(:name).and_return('Dummy')
   end
 
+  describe '.series' do
+    it 'returns a String' do
+      expect(described_class.series).to be_an_instance_of(String)
+    end
+  end
+
   describe '.configure' do
     it 'yields self' do
       described_class.configure do |c|
@@ -78,8 +84,7 @@ describe Gitlab::Metrics::Instrumentation do
         allow(described_class).to receive(:transaction).
           and_return(transaction)
 
-        expect(transaction).to receive(:measure_method).
-          with('Dummy.foo')
+        expect_any_instance_of(Gitlab::Metrics::MethodCall).to receive(:measure)
 
         @dummy.foo
       end
@@ -157,8 +162,7 @@ describe Gitlab::Metrics::Instrumentation do
         allow(described_class).to receive(:transaction).
           and_return(transaction)
 
-        expect(transaction).to receive(:measure_method).
-          with('Dummy#bar')
+        expect_any_instance_of(Gitlab::Metrics::MethodCall).to receive(:measure)
 
         @dummy.new.bar
       end

spec/lib/gitlab/metrics/system_spec.rb

@@ -28,20 +28,20 @@ describe Gitlab::Metrics::System do
   end
 
   describe '.cpu_time' do
-    it 'returns a Float' do
-      expect(described_class.cpu_time).to be_an_instance_of(Float)
+    it 'returns a Fixnum' do
+      expect(described_class.cpu_time).to be_an_instance_of(Fixnum)
     end
   end
 
   describe '.real_time' do
-    it 'returns a Float' do
-      expect(described_class.real_time).to be_an_instance_of(Float)
+    it 'returns a Fixnum' do
+      expect(described_class.real_time).to be_an_instance_of(Fixnum)
     end
   end
 
   describe '.monotonic_time' do
-    it 'returns a Float' do
-      expect(described_class.monotonic_time).to be_an_instance_of(Float)
+    it 'returns a Fixnum' do
+      expect(described_class.monotonic_time).to be_an_instance_of(Fixnum)
     end
   end
 end

spec/lib/gitlab/metrics/transaction_spec.rb

@@ -46,19 +46,11 @@ 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' }
+  describe '#method_call_for' do
+    it 'returns a MethodCall' do
+      method = transaction.method_call_for('Foo#bar')
 
-      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)
+      expect(method).to be_an_instance_of(Gitlab::Metrics::MethodCall)
     end
   end
 

spec/lib/gitlab/metrics_spec.rb

@@ -147,4 +147,10 @@ describe Gitlab::Metrics do
       end
     end
   end
+
+  describe '#series_prefix' do
+    it 'returns a String' do
+      expect(described_class.series_prefix).to be_an_instance_of(String)
+    end
+  end
 end