Use clock_gettime for all performance timestampsperformance-clock-adjustments

Process.clock_gettime allows getting the real time in nanoseconds as
well as allowing one to get a monotonic timestamp. This offers greater
accuracy without the overhead of having to allocate a Time instance. In
general using Time.now/Time.new is about 2x slower than using
Process.clock_gettime(). For example:

    require 'benchmark/ips'

    Benchmark.ips do |bench|
      bench.report 'Time.now' do
        Time.now.to_f
      end

      bench.report 'clock_gettime' do
        Process.clock_gettime(Process::CLOCK_MONOTONIC, :millisecond)
      end

      bench.compare!
    end

Running this benchmark gives:

    Calculating -------------------------------------
                Time.now   108.052k i/100ms
           clock_gettime   125.984k i/100ms
    -------------------------------------------------
                Time.now      2.343M (± 7.1%) i/s -     11.670M
           clock_gettime      4.979M (± 0.8%) i/s -     24.945M

    Comparison:
           clock_gettime:  4979393.8 i/s
                Time.now:  2342986.8 i/s - 2.13x slower

Another benefit of using Process.clock_gettime() is that we can simplify
the code a bit since it can give timestamps in nanoseconds out of the
box.

5 files changed, 48 insertions, 21 deletions

diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb
index faf0d9b6318..c048fe20ba7 100644
--- a/lib/gitlab/metrics/method_call.rb
+++ b/lib/gitlab/metrics/method_call.rb
@@ -18,12 +18,12 @@ module Gitlab
 
       # Measures the real and CPU execution time of the supplied block.
       def measure
-        start_real = Time.now
+        start_real = System.monotonic_time
         start_cpu = System.cpu_time
         retval = yield
 
-        @real_time += (Time.now - start_real) * 1000.0
-        @cpu_time += System.cpu_time.to_f - start_cpu
+        @real_time += System.monotonic_time - start_real
+        @cpu_time += System.cpu_time - start_cpu
         @call_count += 1
 
         retval
diff --git a/lib/gitlab/metrics/metric.rb b/lib/gitlab/metrics/metric.rb
index 1cd1ca30f70..f23d67e1e38 100644
--- a/lib/gitlab/metrics/metric.rb
+++ b/lib/gitlab/metrics/metric.rb
@@ -4,16 +4,15 @@ module Gitlab
     class Metric
       JITTER_RANGE = 0.000001..0.001
 
-      attr_reader :series, :values, :tags, :created_at
+      attr_reader :series, :values, :tags
 
       # series - The name of the series (as a String) to store the metric in.
       # values - A Hash containing the values to store.
       # tags   - A Hash containing extra tags to add to the metrics.
       def initialize(series, values, tags = {})
-        @values     = values
-        @series     = series
-        @tags       = tags
-        @created_at = Time.now.utc
+        @values = values
+        @series = series
+        @tags   = tags
       end
 
       # Returns a Hash in a format that can be directly written to InfluxDB.
@@ -27,20 +26,20 @@ module Gitlab
         #
         # Due to the way InfluxDB is set up there's no solution to this problem,
         # all we can do is lower the amount of collisions. We do this by using
-        # Time#to_f which returns the seconds as a Float providing greater
-        # accuracy. We then add a small random value that is large enough to
-        # distinguish most timestamps but small enough to not alter the amount
-        # of seconds.
+        # System.real_time which returns the nanoseconds as a Float providing
+        # greater accuracy. We then add a small random value that is large
+        # enough to distinguish most timestamps but small enough to not alter
+        # the timestamp significantly.
         #
         # See https://gitlab.com/gitlab-com/operations/issues/175 for more
         # information.
-        time = @created_at.to_f + rand(JITTER_RANGE)
+        time = System.real_time(:nanosecond) + rand(JITTER_RANGE)
 
         {
           series:    @series,
           tags:      @tags,
           values:    @values,
-          timestamp: (time * 1_000_000_000).to_i
+          timestamp: time.to_i
         }
       end
     end
diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb
index a7d183b2f94..82c18bb108b 100644
--- a/lib/gitlab/metrics/system.rb
+++ b/lib/gitlab/metrics/system.rb
@@ -34,13 +34,29 @@ module Gitlab
       # 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)
+          Process.
+            clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond).to_f
         end
       else
         def self.cpu_time
-          Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond)
+          Process.
+            clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond).to_f
         end
       end
+
+      # Returns the current real time in a given precision.
+      #
+      # Returns the time as a Float.
+      def self.real_time(precision = :millisecond)
+        Process.clock_gettime(Process::CLOCK_REALTIME, precision).to_f
+      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
+      end
     end
   end
 end
diff --git a/lib/gitlab/metrics/transaction.rb b/lib/gitlab/metrics/transaction.rb
index 4bc5081aa03..bded245da43 100644
--- a/lib/gitlab/metrics/transaction.rb
+++ b/lib/gitlab/metrics/transaction.rb
@@ -30,7 +30,7 @@ module Gitlab
       end
 
       def duration
-        @finished_at ? (@finished_at - @started_at) * 1000.0 : 0.0
+        @finished_at ? (@finished_at - @started_at) : 0.0
       end
 
       def allocated_memory
@@ -41,12 +41,12 @@ module Gitlab
         Thread.current[THREAD_KEY] = self
 
         @memory_before = System.memory_usage
-        @started_at    = Time.now
+        @started_at    = System.monotonic_time
 
         yield
       ensure
         @memory_after = System.memory_usage
-        @finished_at  = Time.now
+        @finished_at  = System.monotonic_time
 
         Thread.current[THREAD_KEY] = nil
       end
diff --git a/spec/lib/gitlab/metrics/system_spec.rb b/spec/lib/gitlab/metrics/system_spec.rb
index d6ae54e25e8..cf0e282c2fb 100644
--- a/spec/lib/gitlab/metrics/system_spec.rb
+++ b/spec/lib/gitlab/metrics/system_spec.rb
@@ -28,8 +28,20 @@ describe Gitlab::Metrics::System do
   end
 
   describe '.cpu_time' do
-    it 'returns a Fixnum' do
-      expect(described_class.cpu_time).to be_an_instance_of(Fixnum)
+    it 'returns a Float' do
+      expect(described_class.cpu_time).to be_an_instance_of(Float)
+    end
+  end
+
+  describe '.real_time' do
+    it 'returns a Float' do
+      expect(described_class.real_time).to be_an_instance_of(Float)
+    end
+  end
+
+  describe '.monotonic_time' do
+    it 'returns a Float' do
+      expect(described_class.monotonic_time).to be_an_instance_of(Float)
     end
   end
 end