Verified Commit d7b4f36a authored by Yorick Peterse's avatar Yorick Peterse
Browse files

Use clock_gettime for all performance timestamps 

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.
parent 7a94432e

lib/gitlab/metrics/method_call.rb

+3 −3
Original line number Diff line number Diff line
@@ -18,12 +18,12 @@ def initialize(name, series) 


      # 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

lib/gitlab/metrics/metric.rb

+10 −11
Original line number Diff line number Diff line
@@ -4,7 +4,7 @@ module Metrics 
    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.
@@ -13,7 +13,6 @@ def initialize(series, values, tags = {}) 
        @values = values

        @series = series

        @tags   = tags

        @created_at = Time.now.utc

      end



      # Returns a Hash in a format that can be directly written to InfluxDB.
@@ -27,20 +26,20 @@ def to_hash 
        #

        # 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

lib/gitlab/metrics/system.rb

+18 −2
Original line number Diff line number Diff line
@@ -34,13 +34,29 @@ def self.file_descriptor_count 
      # 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

lib/gitlab/metrics/transaction.rb

+3 −3
Original line number Diff line number Diff line
@@ -30,7 +30,7 @@ def initialize(action = nil) 
      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 @@ def run 
        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

spec/lib/gitlab/metrics/system_spec.rb

+14 −2
Original line number Diff line number Diff line
@@ -28,8 +28,20 @@ 
  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