From d7b4f36a3cc691ba5684c1bbc48cc22c59228ca8 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Fri, 24 Jun 2016 13:44:50 +0200 Subject: Use clock_gettime for all performance timestamps MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- lib/gitlab/metrics/method_call.rb | 6 +++--- lib/gitlab/metrics/metric.rb | 21 ++++++++++----------- lib/gitlab/metrics/system.rb | 20 ++++++++++++++++++-- lib/gitlab/metrics/transaction.rb | 6 +++--- spec/lib/gitlab/metrics/system_spec.rb | 16 ++++++++++++++-- 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 -- cgit v1.2.1