From be3b8784431d8f788d174fce2f1b17ddc1cf3429 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Fri, 17 Jun 2016 17:45:37 +0200 Subject: [PATCH] Track method call times/counts as a single metric Previously we'd create a separate Metric instance for every method call that would exceed the method call threshold. This is problematic because it doesn't provide us with information to accurately get the _total_ execution time of a particular method. For example, if the method "Foo#bar" was called 4 times with a runtime of ~10 milliseconds we'd end up with 4 different Metric instances. If we were to then get the average/95th percentile/etc of the timings this would be roughly 10 milliseconds. However, the _actual_ total time spent in this method would be around 40 milliseconds. To solve this problem we now create a single Metric instance per method. This Metric instance contains the _total_ real/CPU time and the call count for every instrumented method. --- CHANGELOG | 1 + doc/development/instrumentation.md | 19 +--- lib/gitlab/metrics/instrumentation.rb | 19 +--- lib/gitlab/metrics/method_call.rb | 52 +++++++++++ lib/gitlab/metrics/transaction.rb | 35 ++++++- .../gitlab/metrics/instrumentation_spec.rb | 10 +- spec/lib/gitlab/metrics/method_call_spec.rb | 91 +++++++++++++++++++ spec/lib/gitlab/metrics/transaction_spec.rb | 16 ++++ 8 files changed, 198 insertions(+), 45 deletions(-) create mode 100644 lib/gitlab/metrics/method_call.rb create mode 100644 spec/lib/gitlab/metrics/method_call_spec.rb diff --git a/CHANGELOG b/CHANGELOG index 620a7eea378..781708741f0 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -36,6 +36,7 @@ v 8.9.0 (unreleased) - Added shortcut 'y' for copying a files content hash URL #14470 - Fix groups API to list only user's accessible projects - Fix horizontal scrollbar for long commit message. + - GitLab Performance Monitoring now tracks the total method execution time and call count per method - Add Environments and Deployments - Redesign account and email confirmation emails - Don't fail builds for projects that are deleted diff --git a/doc/development/instrumentation.md b/doc/development/instrumentation.md index 6cd9b274d11..c2272ab0a2b 100644 --- a/doc/development/instrumentation.md +++ b/doc/development/instrumentation.md @@ -94,23 +94,8 @@ Visibility: public Number of lines: 21 def #{name}(#{args_signature}) - trans = Gitlab::Metrics::Instrumentation.transaction - - if trans - start = Time.now - cpu_start = Gitlab::Metrics::System.cpu_time - retval = super - duration = (Time.now - start) * 1000.0 - - if duration >= Gitlab::Metrics.method_call_threshold - cpu_duration = Gitlab::Metrics::System.cpu_time - cpu_start - - trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES, - { duration: duration, cpu_duration: cpu_duration }, - method: #{label.inspect}) - end - - retval + if trans = Gitlab::Metrics::Instrumentation.transaction + trans.measure_method(#{label.inspect}) { super } else super end diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index d81d26754fe..dcec7543c13 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -148,23 +148,8 @@ module Gitlab proxy_module.class_eval <<-EOF, __FILE__, __LINE__ + 1 def #{name}(#{args_signature}) - trans = Gitlab::Metrics::Instrumentation.transaction - - if trans - start = Time.now - cpu_start = Gitlab::Metrics::System.cpu_time - retval = super - duration = (Time.now - start) * 1000.0 - - if duration >= Gitlab::Metrics.method_call_threshold - cpu_duration = Gitlab::Metrics::System.cpu_time - cpu_start - - trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES, - { duration: duration, cpu_duration: cpu_duration }, - method: #{label.inspect}) - end - - retval + if trans = Gitlab::Metrics::Instrumentation.transaction + trans.measure_method(#{label.inspect}) { super } else super end diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb new file mode 100644 index 00000000000..faf0d9b6318 --- /dev/null +++ b/lib/gitlab/metrics/method_call.rb @@ -0,0 +1,52 @@ +module Gitlab + module Metrics + # Class for tracking timing information about method calls + class MethodCall + attr_reader :real_time, :cpu_time, :call_count + + # name - The full name of the method (including namespace) such as + # `User#sign_in`. + # + # series - The series to use for storing the data. + def initialize(name, series) + @name = name + @series = series + @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 = Time.now + start_cpu = System.cpu_time + retval = yield + + @real_time += (Time.now - start_real) * 1000.0 + @cpu_time += System.cpu_time.to_f - start_cpu + @call_count += 1 + + retval + end + + # Returns a Metric instance of the current method call. + def to_metric + Metric.new( + @series, + { + duration: real_time, + cpu_duration: cpu_time, + call_count: call_count + }, + method: @name + ) + end + + # Returns true if the total runtime of this method exceeds the method call + # threshold. + def above_threshold? + real_time >= Metrics.method_call_threshold + end + end + end +end diff --git a/lib/gitlab/metrics/transaction.rb b/lib/gitlab/metrics/transaction.rb index 2578ddc49f4..4bc5081aa03 100644 --- a/lib/gitlab/metrics/transaction.rb +++ b/lib/gitlab/metrics/transaction.rb @@ -4,7 +4,7 @@ module Gitlab class Transaction THREAD_KEY = :_gitlab_metrics_transaction - attr_reader :tags, :values + attr_reader :tags, :values, :methods attr_accessor :action @@ -16,6 +16,7 @@ module Gitlab # plus method name. def initialize(action = nil) @metrics = [] + @methods = {} @started_at = nil @finished_at = nil @@ -51,9 +52,23 @@ module Gitlab end def add_metric(series, values, tags = {}) - prefix = sidekiq? ? 'sidekiq_' : 'rails_' + @metrics << Metric.new("#{series_prefix}#{series}", values, tags) + end - @metrics << Metric.new("#{prefix}#{series}", values, tags) + # Measures the time it takes to execute a method. + # + # Multiple calls to the same method add up to the total runtime of the + # method. + # + # name - The full name of the method to measure (e.g. `User#sign_in`). + def measure_method(name, &block) + unless @methods[name] + series = "#{series_prefix}#{Instrumentation::SERIES}" + + @methods[name] = MethodCall.new(name, series) + end + + @methods[name].measure(&block) end def increment(name, value) @@ -84,7 +99,13 @@ module Gitlab end def submit - metrics = @metrics.map do |metric| + submit = @metrics.dup + + @methods.each do |name, method| + submit << method.to_metric if method.above_threshold? + end + + submit_hashes = submit.map do |metric| hash = metric.to_hash hash[:tags][:action] ||= @action if @action @@ -92,12 +113,16 @@ module Gitlab hash end - Metrics.submit_metrics(metrics) + Metrics.submit_metrics(submit_hashes) end def sidekiq? Sidekiq.server? end + + def series_prefix + sidekiq? ? 'sidekiq_' : 'rails_' + end end end end diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb index cdf641341cb..8809b7e3f12 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -78,9 +78,8 @@ describe Gitlab::Metrics::Instrumentation do allow(described_class).to receive(:transaction). and_return(transaction) - expect(transaction).to receive(:add_metric). - with(described_class::SERIES, hash_including(:duration, :cpu_duration), - method: 'Dummy.foo') + expect(transaction).to receive(:measure_method). + with('Dummy.foo') @dummy.foo end @@ -158,9 +157,8 @@ describe Gitlab::Metrics::Instrumentation do allow(described_class).to receive(:transaction). and_return(transaction) - expect(transaction).to receive(:add_metric). - with(described_class::SERIES, hash_including(:duration, :cpu_duration), - method: 'Dummy#bar') + expect(transaction).to receive(:measure_method). + with('Dummy#bar') @dummy.new.bar end diff --git a/spec/lib/gitlab/metrics/method_call_spec.rb b/spec/lib/gitlab/metrics/method_call_spec.rb new file mode 100644 index 00000000000..8d05081eecb --- /dev/null +++ b/spec/lib/gitlab/metrics/method_call_spec.rb @@ -0,0 +1,91 @@ +require 'spec_helper' + +describe Gitlab::Metrics::MethodCall do + let(:method_call) { described_class.new('Foo#bar', 'foo') } + + describe '#measure' 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.cpu_time).to be_a_kind_of(Numeric) + expect(method_call.call_count).to eq(1) + end + end + + describe '#to_metric' do + it 'returns a Metric instance' do + method_call.measure { 'foo' } + metric = method_call.to_metric + + expect(metric).to be_an_instance_of(Gitlab::Metrics::Metric) + expect(metric.series).to eq('foo') + + expect(metric.values[:duration]).to be_a_kind_of(Numeric) + expect(metric.values[:cpu_duration]).to be_a_kind_of(Numeric) + expect(metric.values[:call_count]).to an_instance_of(Fixnum) + + expect(metric.tags).to eq({ method: 'Foo#bar' }) + end + end + + describe '#above_threshold?' do + it 'returns false when the total call time is not above the threshold' do + 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.above_threshold?).to eq(true) + end + end + + describe '#call_count' do + context 'without any method calls' do + it 'returns 0' do + expect(method_call.call_count).to eq(0) + end + end + + context 'with method calls' do + it 'returns the number of method calls' do + method_call.measure { 'foo' } + + expect(method_call.call_count).to eq(1) + end + end + end + + describe '#cpu_time' do + context 'without timings' do + it 'returns 0.0' do + expect(method_call.cpu_time).to eq(0.0) + end + end + + context 'with timings' do + it 'returns the total CPU time' do + method_call.measure { 'foo' } + + expect(method_call.cpu_time >= 0.0).to be(true) + end + end + end + + describe '#real_time' do + context 'without timings' do + it 'returns 0.0' do + expect(method_call.real_time).to eq(0.0) + end + end + + context 'with timings' do + it 'returns the total real time' do + method_call.measure { 'foo' } + + expect(method_call.real_time >= 0.0).to be(true) + end + end + end +end diff --git a/spec/lib/gitlab/metrics/transaction_spec.rb b/spec/lib/gitlab/metrics/transaction_spec.rb index 1d5a51a157e..3b1c67a2147 100644 --- a/spec/lib/gitlab/metrics/transaction_spec.rb +++ b/spec/lib/gitlab/metrics/transaction_spec.rb @@ -46,6 +46,22 @@ describe Gitlab::Metrics::Transaction do end end + describe '#measure_method' do + it 'adds a new method if it does not exist already' do + transaction.measure_method('Foo#bar') { 'foo' } + + expect(transaction.methods['Foo#bar']). + to be_an_instance_of(Gitlab::Metrics::MethodCall) + end + + it 'adds timings to an existing method call' do + transaction.measure_method('Foo#bar') { 'foo' } + transaction.measure_method('Foo#bar') { 'foo' } + + expect(transaction.methods['Foo#bar'].call_count).to eq(2) + end + end + describe '#increment' do it 'increments a counter' do transaction.increment(:time, 1)