diff --git a/CHANGELOG b/CHANGELOG index c0bfe8db0769450f13eeac2232e5cba60b37b486..374bb153c56255d557c81c2cbd00c5970b9ee641 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 6cd9b274d115a86815e55a7bc43d4c56d9b94b15..c2272ab0a2bb844af263a53de2c543fe142677b1 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 d81d26754fe004934a19cbcdd3b6f8d17d0bd981..dcec7543c1398c8fde71cf6c888743ac892705ca 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 0000000000000000000000000000000000000000..faf0d9b6318f8a9da2f260ce9827e1f1597cb0af --- /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 2578ddc49f46837e92aae2373c7a3f0a488e3cca..4bc5081aa0361e7c2879b39fc3c3120cefd95363 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 + + # 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 - @metrics << Metric.new("#{prefix}#{series}", values, tags) + @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 cdf641341cbe6ba56b7c2d12c21477962a99b0b7..8809b7e3f1201aae071954568a94d0576bcd837e 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 0000000000000000000000000000000000000000..8d05081eecbce700006d2265264f1bb574b0a21d --- /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 1d5a51a157ea91b84df9f99cb037ecb42915ec21..3b1c67a21478d41ee6d1ebcd071b658b1561b09b 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)