Merge branch 'metrics-measure-block-transaction' into 'master'

Store block timings as transaction values

See merge request !3649

doc/development/instrumentation.md

@@ -2,36 +2,35 @@
 
 GitLab Performance Monitoring allows instrumenting of custom blocks of Ruby
 code. This can be used to measure the time spent in a specific part of a larger
-chunk of code. The resulting data is written to a separate series.
+chunk of code. The resulting data is stored as a field in the transaction that
+executed the block.
 
-To start measuring a block of Ruby code you should use
-`Gitlab::Metrics.measure` and give it a name for the series to store the data
-in:
+To start measuring a block of Ruby code you should use `Gitlab::Metrics.measure`
+and give it a name:
 
 ```ruby
-Gitlab::Metrics.measure(:user_logins) do
+Gitlab::Metrics.measure(:foo) do
   ...
 end
 ```
 
-The first argument of this method is the series name and should be plural. This
-name will be prefixed with `rails_` or `sidekiq_` depending on whether the code
-was run in the Rails application or one of the Sidekiq workers. In the
-above example the final series names would be as follows:
+3 values are measured for a block:
 
-- rails_user_logins
-- sidekiq_user_logins
+1. The real time elapsed, stored in NAME_real_time.
+2. The CPU time elapsed, stored in NAME_cpu_time.
+3. The call count, stored in NAME_call_count.
 
-Series names should be plural as this keeps the naming style in line with the
-other series names.
+Both the real and CPU timings are measured in milliseconds.
 
-By default metrics measured using a block contain a single value, "duration",
-which contains the number of milliseconds it took to execute the block. Custom
-values can be added by passing a Hash as the 2nd argument. Custom tags can be
-added by passing a Hash as the 3rd argument. A simple example is as follows:
+Multiple calls to the same block will result in the final values being the sum
+of all individual values. Take this code for example:
 
 ```ruby
-Gitlab::Metrics.measure(:example_series, { number: 10 }, { class: self.class.to_s }) do
-  ...
+3.times do
+  Gitlab::Metrics.measure(:sleep) do
+    sleep 1
+  end
 end
 ```
+
+Here the final value of `sleep_real_time` will be `3`, _not_ `1`.

lib/gitlab/metrics.rb

@@ -74,24 +74,32 @@ module Gitlab
     #
     # Example:
     #
-    #     Gitlab::Metrics.measure(:find_by_username_timings) do
+    #     Gitlab::Metrics.measure(:find_by_username_duration) do
     #       User.find_by_username(some_username)
     #     end
     #
-    # series - The name of the series to store the data in.
-    # values - A Hash containing extra values to add to the metric.
-    # tags - A Hash containing extra tags to add to the metric.
+    # name - The name of the field to store the execution time in.
     #
     # Returns the value yielded by the supplied block.
-    def self.measure(series, values = {}, tags = {})
-      return yield unless Transaction.current
+    def self.measure(name)
+      trans = current_transaction
+
+      return yield unless trans
+
+      real_start = Time.now.to_f
+      cpu_start = System.cpu_time
 
-      start = Time.now.to_f
       retval = yield
-      duration = (Time.now.to_f - start) * 1000.0
-      values = values.merge(duration: duration)
 
-      Transaction.current.add_metric(series, values, tags)
+      cpu_stop = System.cpu_time
+      real_stop = Time.now.to_f
+
+      real_time = (real_stop - real_start) * 1000.0
+      cpu_time = cpu_stop - cpu_start
+
+      trans.increment("#{name}_real_time", real_time)
+      trans.increment("#{name}_cpu_time", cpu_time)
+      trans.increment("#{name}_call_count", 1)
 
       retval
     end
@@ -107,5 +115,11 @@ module Gitlab
           new(udp: { host: host, port: port })
       end
     end
+
+    private
+
+    def self.current_transaction
+      Transaction.current
+    end
   end
 end

lib/gitlab/metrics/system.rb

@@ -30,6 +30,17 @@ module Gitlab
           0
         end
       end
+
+      # THREAD_CPUTIME is not supported on OS X
+      if Process.const_defined?(:CLOCK_THREAD_CPUTIME_ID)
+        def self.cpu_time
+          Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond)
+        end
+      else
+        def self.cpu_time
+          Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond)
+        end
+      end
     end
   end
 end

spec/lib/gitlab/metrics/system_spec.rb

@@ -26,4 +26,10 @@ describe Gitlab::Metrics::System do
       end
     end
   end
+
+  describe '.cpu_time' do
+    it 'returns a Fixnum' do
+      expect(described_class.cpu_time).to be_an_instance_of(Fixnum)
+    end
+  end
 end

spec/lib/gitlab/metrics_spec.rb

@@ -74,24 +74,21 @@ describe Gitlab::Metrics do
       let(:transaction) { Gitlab::Metrics::Transaction.new }
 
       before do
-        allow(Gitlab::Metrics::Transaction).to receive(:current).
+        allow(Gitlab::Metrics).to receive(:current_transaction).
           and_return(transaction)
       end
 
       it 'adds a metric to the current transaction' do
-        expect(transaction).to receive(:add_metric).
-          with(:foo, { duration: a_kind_of(Numeric) }, { tag: 'value' })
+        expect(transaction).to receive(:increment).
+          with('foo_real_time', a_kind_of(Numeric))
 
-        Gitlab::Metrics.measure(:foo, {}, tag: 'value') { 10 }
-      end
-
-      it 'supports adding of custom values' do
-        values = { duration: a_kind_of(Numeric), number: 10 }
+        expect(transaction).to receive(:increment).
+          with('foo_cpu_time', a_kind_of(Numeric))
 
-        expect(transaction).to receive(:add_metric).
-          with(:foo, values, { tag: 'value' })
+        expect(transaction).to receive(:increment).
+          with('foo_call_count', 1)
 
-        Gitlab::Metrics.measure(:foo, { number: 10 }, tag: 'value') { 10 }
+        Gitlab::Metrics.measure(:foo) { 10 }
       end
 
       it 'returns the return value of the block' do