From a8ebed6016726722a2283458e4176fc9177558af Mon Sep 17 00:00:00 2001 From: Pawel Chojnacki Date: Tue, 12 Dec 2017 18:12:49 +0100 Subject: [PATCH] Make `System.monotonic_time` retun seconds represented by float with microsecond precision --- lib/gitlab/gitaly_client.rb | 2 +- lib/gitlab/metrics/method_call.rb | 18 +++++++++++------- lib/gitlab/metrics/samplers/ruby_sampler.rb | 2 +- lib/gitlab/metrics/system.rb | 9 +++++---- lib/gitlab/metrics/transaction.rb | 8 ++++++-- spec/lib/gitlab/metrics/system_spec.rb | 4 ++-- 6 files changed, 26 insertions(+), 17 deletions(-) diff --git a/lib/gitlab/gitaly_client.rb b/lib/gitlab/gitaly_client.rb index 7aa2eafbb73..b753ac46291 100644 --- a/lib/gitlab/gitaly_client.rb +++ b/lib/gitlab/gitaly_client.rb @@ -132,7 +132,7 @@ module Gitlab self.query_time += duration gitaly_call_histogram.observe( current_transaction_labels.merge(gitaly_service: service.to_s, rpc: rpc.to_s), - duration / 1000.0) + duration) end def self.current_transaction_labels diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb index 65d55576ac2..6fb8f564237 100644 --- a/lib/gitlab/metrics/method_call.rb +++ b/lib/gitlab/metrics/method_call.rb @@ -4,7 +4,7 @@ module Gitlab class MethodCall MUTEX = Mutex.new BASE_LABELS = { module: nil, method: nil }.freeze - attr_reader :real_time, :cpu_time, :call_count, :labels + attr_reader :real_time_seconds, :cpu_time, :call_count, :labels def self.call_duration_histogram return @call_duration_histogram if @call_duration_histogram @@ -27,37 +27,41 @@ module Gitlab @transaction = transaction @name = name @labels = { module: @module_name, method: @method_name } - @real_time = 0 + @real_time_seconds = 0 @cpu_time = 0 @call_count = 0 end # Measures the real and CPU execution time of the supplied block. def measure - start_real = System.monotonic_time + start_real_seconds = System.monotonic_time start_cpu = System.cpu_time retval = yield - real_time = System.monotonic_time - start_real + real_time_seconds = System.monotonic_time - start_real_seconds cpu_time = System.cpu_time - start_cpu - @real_time += real_time + @real_time_seconds += real_time_seconds @cpu_time += cpu_time @call_count += 1 if call_measurement_enabled? && above_threshold? - self.class.call_duration_histogram.observe(@transaction.labels.merge(labels), real_time / 1000.0) + self.class.call_duration_histogram.observe(@transaction.labels.merge(labels), real_time_seconds) end retval end + def real_time_milliseconds + (real_time_seconds * 1000.0).to_i + end + # Returns a Metric instance of the current method call. def to_metric Metric.new( Instrumentation.series, { - duration: real_time, + duration: real_time_milliseconds, cpu_duration: cpu_time, call_count: call_count }, diff --git a/lib/gitlab/metrics/samplers/ruby_sampler.rb b/lib/gitlab/metrics/samplers/ruby_sampler.rb index b68800417a2..4e1ea62351f 100644 --- a/lib/gitlab/metrics/samplers/ruby_sampler.rb +++ b/lib/gitlab/metrics/samplers/ruby_sampler.rb @@ -52,7 +52,7 @@ module Gitlab metrics[:memory_usage].set(labels, System.memory_usage) metrics[:file_descriptors].set(labels, System.file_descriptor_count) - metrics[:sampler_duration].observe(labels.merge(worker_label), (System.monotonic_time - start_time) / 1000.0) + metrics[:sampler_duration].observe(labels.merge(worker_label), System.monotonic_time - start_time) ensure GC::Profiler.clear end diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb index c2cbd3c16a1..b31cc6236d1 100644 --- a/lib/gitlab/metrics/system.rb +++ b/lib/gitlab/metrics/system.rb @@ -51,11 +51,12 @@ module Gitlab Process.clock_gettime(Process::CLOCK_REALTIME, precision) end - # Returns the current monotonic clock time in a given precision. + # Returns the current monotonic clock time as seconds with microseconds precision. # - # Returns the time as a Fixnum. - def self.monotonic_time(precision = :millisecond) - Process.clock_gettime(Process::CLOCK_MONOTONIC, precision) + # Returns the time as a Float. + def self.monotonic_time + + Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second) end end end diff --git a/lib/gitlab/metrics/transaction.rb b/lib/gitlab/metrics/transaction.rb index ee3afc5ffdb..16f0969ab74 100644 --- a/lib/gitlab/metrics/transaction.rb +++ b/lib/gitlab/metrics/transaction.rb @@ -35,6 +35,10 @@ module Gitlab @finished_at ? (@finished_at - @started_at) : 0.0 end + def duration_milliseconds + (duration * 1000).to_i + end + def allocated_memory @memory_after - @memory_before end @@ -50,7 +54,7 @@ module Gitlab @memory_after = System.memory_usage @finished_at = System.monotonic_time - self.class.metric_transaction_duration_seconds.observe(labels, duration * 1000) + self.class.metric_transaction_duration_seconds.observe(labels, duration) self.class.metric_transaction_allocated_memory_bytes.observe(labels, allocated_memory * 1024.0) Thread.current[THREAD_KEY] = nil @@ -97,7 +101,7 @@ module Gitlab end def track_self - values = { duration: duration, allocated_memory: allocated_memory } + values = { duration: duration_milliseconds, allocated_memory: allocated_memory } @values.each do |name, value| values[name] = value diff --git a/spec/lib/gitlab/metrics/system_spec.rb b/spec/lib/gitlab/metrics/system_spec.rb index 4d94d8705fb..ea3bd00970e 100644 --- a/spec/lib/gitlab/metrics/system_spec.rb +++ b/spec/lib/gitlab/metrics/system_spec.rb @@ -40,8 +40,8 @@ describe Gitlab::Metrics::System do end describe '.monotonic_time' do - it 'returns a Fixnum' do - expect(described_class.monotonic_time).to be_an(Integer) + it 'returns a Float' do + expect(described_class.monotonic_time).to be_an(Float) end end end