From e391fe1d6d39837d6aebb14f90e200fc6ff42d81 Mon Sep 17 00:00:00 2001 From: Pawel Chojnacki Date: Tue, 12 Dec 2017 15:11:34 +0100 Subject: Reduce cardinality of gitlab_cache_operation_duration_seconds histogram --- lib/gitlab/metrics/subscribers/rails_cache.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/gitlab/metrics/subscribers/rails_cache.rb b/lib/gitlab/metrics/subscribers/rails_cache.rb index efd3c9daf79..250897a79c2 100644 --- a/lib/gitlab/metrics/subscribers/rails_cache.rb +++ b/lib/gitlab/metrics/subscribers/rails_cache.rb @@ -66,7 +66,7 @@ module Gitlab :gitlab_cache_operation_duration_seconds, 'Cache access time', Transaction::BASE_LABELS.merge({ action: nil }), - [0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1, 0.500, 2.0, 10.0] + [0.001, 0.01, 0.1, 1, 10] ) end -- cgit v1.2.1 From b02db1f4931060d9e28bd0d651dbea34c79340e2 Mon Sep 17 00:00:00 2001 From: Pawel Chojnacki Date: Tue, 12 Dec 2017 16:54:11 +0100 Subject: Fix gitaly_call_histogram to observe times in seconds correctly --- lib/gitlab/gitaly_client.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/gitlab/gitaly_client.rb b/lib/gitlab/gitaly_client.rb index b753ac46291..7aa2eafbb73 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) + duration / 1000.0) end def self.current_transaction_labels -- cgit v1.2.1 From a8ebed6016726722a2283458e4176fc9177558af Mon Sep 17 00:00:00 2001 From: Pawel Chojnacki Date: Tue, 12 Dec 2017 18:12:49 +0100 Subject: 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 -- cgit v1.2.1 From 3c545133e8f23b57698046bae8be23e2bc457aca Mon Sep 17 00:00:00 2001 From: Pawel Chojnacki Date: Tue, 19 Dec 2017 17:45:25 +0100 Subject: Fix tests and formatting --- lib/gitlab/metrics/influx_db.rb | 1 + lib/gitlab/metrics/method_call.rb | 2 +- lib/gitlab/metrics/system.rb | 1 - spec/lib/gitlab/metrics/method_call_spec.rb | 11 ++++++----- 4 files changed, 8 insertions(+), 7 deletions(-) diff --git a/lib/gitlab/metrics/influx_db.rb b/lib/gitlab/metrics/influx_db.rb index bdf7910b7c7..153e236d018 100644 --- a/lib/gitlab/metrics/influx_db.rb +++ b/lib/gitlab/metrics/influx_db.rb @@ -38,6 +38,7 @@ module Gitlab # This is memoized since this method is called for every instrumented # method. Loading data from an external cache on every method call slows # things down too much. + # in milliseconds @method_call_threshold ||= settings[:method_call_threshold] end diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb index 6fb8f564237..a030092df37 100644 --- a/lib/gitlab/metrics/method_call.rb +++ b/lib/gitlab/metrics/method_call.rb @@ -72,7 +72,7 @@ module Gitlab # Returns true if the total runtime of this method exceeds the method call # threshold. def above_threshold? - real_time >= Metrics.method_call_threshold + real_time_milliseconds >= Metrics.method_call_threshold end def call_measurement_enabled? diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb index b31cc6236d1..4852017bf38 100644 --- a/lib/gitlab/metrics/system.rb +++ b/lib/gitlab/metrics/system.rb @@ -55,7 +55,6 @@ module Gitlab # # Returns the time as a Float. def self.monotonic_time - Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second) end end diff --git a/spec/lib/gitlab/metrics/method_call_spec.rb b/spec/lib/gitlab/metrics/method_call_spec.rb index 5341addf911..91a70ba01a0 100644 --- a/spec/lib/gitlab/metrics/method_call_spec.rb +++ b/spec/lib/gitlab/metrics/method_call_spec.rb @@ -8,7 +8,8 @@ describe Gitlab::Metrics::MethodCall do it 'measures the performance of the supplied block' do method_call.measure { 'foo' } - expect(method_call.real_time).to be_a_kind_of(Numeric) + expect(method_call.real_time_seconds).to be_a_kind_of(Numeric) + expect(method_call.real_time_milliseconds).to be_a_kind_of(Numeric) expect(method_call.cpu_time).to be_a_kind_of(Numeric) expect(method_call.call_count).to eq(1) end @@ -84,13 +85,13 @@ describe Gitlab::Metrics::MethodCall do end it 'returns false when the total call time is not above the threshold' do - expect(method_call).to receive(:real_time).and_return(9) + expect(method_call).to receive(:real_time_seconds).and_return(0.009) expect(method_call.above_threshold?).to eq(false) end it 'returns true when the total call time is above the threshold' do - expect(method_call).to receive(:real_time).and_return(9000) + expect(method_call).to receive(:real_time_seconds).and_return(9) expect(method_call.above_threshold?).to eq(true) end @@ -131,7 +132,7 @@ describe Gitlab::Metrics::MethodCall do describe '#real_time' do context 'without timings' do it 'returns 0.0' do - expect(method_call.real_time).to eq(0.0) + expect(method_call.real_time_seconds).to eq(0.0) end end @@ -139,7 +140,7 @@ describe Gitlab::Metrics::MethodCall do it 'returns the total real time' do method_call.measure { 'foo' } - expect(method_call.real_time >= 0.0).to be(true) + expect(method_call.real_time_seconds >= 0.0).to be(true) end end end -- cgit v1.2.1 From ed715b7926c31fddb1c835823d509672663e23e6 Mon Sep 17 00:00:00 2001 From: Pawel Chojnacki Date: Tue, 19 Dec 2017 19:40:43 +0100 Subject: use in_milliseconds rails helper --- lib/gitlab/metrics/method_call.rb | 4 ++-- lib/gitlab/metrics/transaction.rb | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb index a030092df37..bb39b1d5462 100644 --- a/lib/gitlab/metrics/method_call.rb +++ b/lib/gitlab/metrics/method_call.rb @@ -27,7 +27,7 @@ module Gitlab @transaction = transaction @name = name @labels = { module: @module_name, method: @method_name } - @real_time_seconds = 0 + @real_time_seconds = 0.0 @cpu_time = 0 @call_count = 0 end @@ -53,7 +53,7 @@ module Gitlab end def real_time_milliseconds - (real_time_seconds * 1000.0).to_i + real_time_seconds.in_milliseconds.to_i end # Returns a Metric instance of the current method call. diff --git a/lib/gitlab/metrics/transaction.rb b/lib/gitlab/metrics/transaction.rb index 16f0969ab74..e7975c023a9 100644 --- a/lib/gitlab/metrics/transaction.rb +++ b/lib/gitlab/metrics/transaction.rb @@ -36,7 +36,7 @@ module Gitlab end def duration_milliseconds - (duration * 1000).to_i + duration.in_milliseconds.to_i end def allocated_memory -- cgit v1.2.1 From 040167f0724027020f2d63b6e43481fb3e29dbfc Mon Sep 17 00:00:00 2001 From: Pawel Chojnacki Date: Wed, 20 Dec 2017 19:30:58 +0100 Subject: Use seconds where possible, and convert to milliseconds for Influxdb consumption --- ...el-reduce_cardinality_of_prometheus_metrics.yml | 5 +++++ lib/gitlab/metrics/method_call.rb | 24 +++++++++------------- lib/gitlab/metrics/system.rb | 8 ++++---- spec/lib/gitlab/metrics/method_call_spec.rb | 18 ++++++++-------- spec/lib/gitlab/metrics/system_spec.rb | 4 ++-- 5 files changed, 31 insertions(+), 28 deletions(-) create mode 100644 changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml diff --git a/changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml b/changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml new file mode 100644 index 00000000000..8213b493903 --- /dev/null +++ b/changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml @@ -0,0 +1,5 @@ +--- +title: Reduce the number of buckets in gitlab_cache_operation_duration_seconds +merge_request: 15881 +author: +type: changed diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb index bb39b1d5462..f4a916f154d 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_seconds, :cpu_time, :call_count, :labels + attr_reader :real_time, :cpu_time, :call_count, :labels def self.call_duration_histogram return @call_duration_histogram if @call_duration_histogram @@ -27,42 +27,38 @@ module Gitlab @transaction = transaction @name = name @labels = { module: @module_name, method: @method_name } - @real_time_seconds = 0.0 - @cpu_time = 0 + @real_time = 0.0 + @cpu_time = 0.0 @call_count = 0 end # Measures the real and CPU execution time of the supplied block. def measure - start_real_seconds = System.monotonic_time + start_real = System.monotonic_time start_cpu = System.cpu_time retval = yield - real_time_seconds = System.monotonic_time - start_real_seconds + real_time = System.monotonic_time - start_real cpu_time = System.cpu_time - start_cpu - @real_time_seconds += real_time_seconds + @real_time += real_time @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_seconds) + self.class.call_duration_histogram.observe(@transaction.labels.merge(labels), real_time) end retval end - def real_time_milliseconds - real_time_seconds.in_milliseconds.to_i - end - # Returns a Metric instance of the current method call. def to_metric Metric.new( Instrumentation.series, { - duration: real_time_milliseconds, - cpu_duration: cpu_time, + duration: real_time.in_milliseconds.to_i, + cpu_duration: cpu_time.in_milliseconds.to_i, call_count: call_count }, method: @name @@ -72,7 +68,7 @@ module Gitlab # Returns true if the total runtime of this method exceeds the method call # threshold. def above_threshold? - real_time_milliseconds >= Metrics.method_call_threshold + real_time.in_milliseconds >= Metrics.method_call_threshold end def call_measurement_enabled? diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb index 4852017bf38..e60e245cf89 100644 --- a/lib/gitlab/metrics/system.rb +++ b/lib/gitlab/metrics/system.rb @@ -35,19 +35,19 @@ module Gitlab if Process.const_defined?(:CLOCK_THREAD_CPUTIME_ID) def self.cpu_time Process - .clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond) + .clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :float_second) end else def self.cpu_time Process - .clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond) + .clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :float_second) end end # Returns the current real time in a given precision. # - # Returns the time as a Fixnum. - def self.real_time(precision = :millisecond) + # Returns the time as a Float for precision = :float_second. + def self.real_time(precision = :float_second) Process.clock_gettime(Process::CLOCK_REALTIME, precision) end diff --git a/spec/lib/gitlab/metrics/method_call_spec.rb b/spec/lib/gitlab/metrics/method_call_spec.rb index 91a70ba01a0..448246ff513 100644 --- a/spec/lib/gitlab/metrics/method_call_spec.rb +++ b/spec/lib/gitlab/metrics/method_call_spec.rb @@ -8,8 +8,7 @@ describe Gitlab::Metrics::MethodCall do it 'measures the performance of the supplied block' do method_call.measure { 'foo' } - expect(method_call.real_time_seconds).to be_a_kind_of(Numeric) - expect(method_call.real_time_milliseconds).to be_a_kind_of(Numeric) + expect(method_call.real_time).to be_a_kind_of(Numeric) expect(method_call.cpu_time).to be_a_kind_of(Numeric) expect(method_call.call_count).to eq(1) end @@ -65,14 +64,17 @@ describe Gitlab::Metrics::MethodCall do describe '#to_metric' do it 'returns a Metric instance' do + expect(method_call).to receive(:real_time).and_return(4.0001) + expect(method_call).to receive(:cpu_time).and_return(3.0001) + method_call.measure { 'foo' } metric = method_call.to_metric expect(metric).to be_an_instance_of(Gitlab::Metrics::Metric) expect(metric.series).to eq('rails_method_calls') - expect(metric.values[:duration]).to be_a_kind_of(Numeric) - expect(metric.values[:cpu_duration]).to be_a_kind_of(Numeric) + expect(metric.values[:duration]).to eq(4000) + expect(metric.values[:cpu_duration]).to eq(3000) expect(metric.values[:call_count]).to be_an(Integer) expect(metric.tags).to eq({ method: 'Foo#bar' }) @@ -85,13 +87,13 @@ describe Gitlab::Metrics::MethodCall do end it 'returns false when the total call time is not above the threshold' do - expect(method_call).to receive(:real_time_seconds).and_return(0.009) + expect(method_call).to receive(:real_time).and_return(0.009) expect(method_call.above_threshold?).to eq(false) end it 'returns true when the total call time is above the threshold' do - expect(method_call).to receive(:real_time_seconds).and_return(9) + expect(method_call).to receive(:real_time).and_return(9) expect(method_call.above_threshold?).to eq(true) end @@ -132,7 +134,7 @@ describe Gitlab::Metrics::MethodCall do describe '#real_time' do context 'without timings' do it 'returns 0.0' do - expect(method_call.real_time_seconds).to eq(0.0) + expect(method_call.real_time).to eq(0.0) end end @@ -140,7 +142,7 @@ describe Gitlab::Metrics::MethodCall do it 'returns the total real time' do method_call.measure { 'foo' } - expect(method_call.real_time_seconds >= 0.0).to be(true) + expect(method_call.real_time >= 0.0).to be(true) end end end diff --git a/spec/lib/gitlab/metrics/system_spec.rb b/spec/lib/gitlab/metrics/system_spec.rb index ea3bd00970e..14afcdf5daa 100644 --- a/spec/lib/gitlab/metrics/system_spec.rb +++ b/spec/lib/gitlab/metrics/system_spec.rb @@ -29,13 +29,13 @@ describe Gitlab::Metrics::System do describe '.cpu_time' do it 'returns a Fixnum' do - expect(described_class.cpu_time).to be_an(Integer) + expect(described_class.cpu_time).to be_an(Float) end end describe '.real_time' do it 'returns a Fixnum' do - expect(described_class.real_time).to be_an(Integer) + expect(described_class.real_time).to be_an(Float) end end -- cgit v1.2.1 From 10af36f0e8dff3629c404adac0e5553086e72481 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pawe=C5=82=20Chojnacki?= Date: Wed, 20 Dec 2017 23:42:37 +0000 Subject: add missing word to pawel-reduce_cardinality_of_prometheus_metrics.yml --- .../unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml b/changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml index 8213b493903..0cee0b634d6 100644 --- a/changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml +++ b/changelogs/unreleased/pawel-reduce_cardinality_of_prometheus_metrics.yml @@ -1,5 +1,5 @@ --- -title: Reduce the number of buckets in gitlab_cache_operation_duration_seconds +title: Reduce the number of buckets in gitlab_cache_operation_duration_seconds metric merge_request: 15881 author: type: changed -- cgit v1.2.1