Store block timings as transaction values

This makes it easier to query, simplifies the code, and makes it
possible to figure out what transaction the data belongs to (simply
because it's now stored _in_ the transaction).

This new setup keeps track of both the real/wall time _and_ CPU time
spent in a block, both measured using milliseconds (to keep all units
the same).

4 files changed, 47 insertions, 39 deletions

diff --git a/doc/development/instrumentation.md b/doc/development/instrumentation.md
index c0192bd6709..f7e148fb3e4 100644
--- a/doc/development/instrumentation.md
+++ b/doc/development/instrumentation.md
@@ -2,36 +2,34 @@
 
 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:
+Two 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
 
-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`.
diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb
index 4a3f47b5a95..4d64555027e 100644
--- a/lib/gitlab/metrics.rb
+++ b/lib/gitlab/metrics.rb
@@ -74,24 +74,29 @@ 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 = {})
+    def self.measure(name)
       return yield unless Transaction.current
 
-      start = Time.now.to_f
+      real_start = Time.now.to_f
+      cpu_start = System.cpu_time
+
       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
+
+      Transaction.current.increment("#{name}_real_time", real_time)
+      Transaction.current.increment("#{name}_cpu_time", cpu_time)
 
       retval
     end
diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb
index 83371265278..a7d183b2f94 100644
--- a/lib/gitlab/metrics/system.rb
+++ b/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
diff --git a/spec/lib/gitlab/metrics_spec.rb b/spec/lib/gitlab/metrics_spec.rb
index 8f63a5f2043..edefec909c9 100644
--- a/spec/lib/gitlab/metrics_spec.rb
+++ b/spec/lib/gitlab/metrics_spec.rb
@@ -79,19 +79,13 @@ describe Gitlab::Metrics do
       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(:add_metric).
-          with(:foo, values, { tag: 'value' })
+        expect(transaction).to receive(:increment).
+          with('foo_cpu_time', a_kind_of(Numeric))
 
-        Gitlab::Metrics.measure(:foo, { number: 10 }, tag: 'value') { 10 }
+        Gitlab::Metrics.measure(:foo) { 10 }
       end
 
       it 'returns the return value of the block' do