From 905f8d763ab1184dc0b1e4bf6f18d7981753a860 Mon Sep 17 00:00:00 2001 From: Yorick Peterse Date: Thu, 28 Jul 2016 15:08:57 +0200 Subject: [PATCH] Reduce instrumentation overhead This reduces the overhead of the method instrumentation code primarily by reducing the number of method calls. There are also some other small optimisations such as not casting timing values to Floats (there's no particular need for this), using Symbols for method call metric names, and reducing the number of Hash lookups for instrumented methods. The exact impact depends on the code being executed. For example, for a method that's only called once the difference won't be very noticeable. However, for methods that are called many times the difference can be more significant. For example, the loading time of a large commit (nrclark/dummy_project@81ebdea5df2fb42e59257cb3eaad671a5c53ca36) was reduced from around 19 seconds to around 15 seconds using these changes. --- CHANGELOG | 1 + lib/gitlab/metrics.rb | 5 ++++ lib/gitlab/metrics/instrumentation.rb | 13 +++++---- lib/gitlab/metrics/method_call.rb | 4 +-- lib/gitlab/metrics/system.rb | 8 +++--- lib/gitlab/metrics/transaction.rb | 27 +++++-------------- .../gitlab/metrics/instrumentation_spec.rb | 12 ++++++--- spec/lib/gitlab/metrics/system_spec.rb | 12 ++++----- spec/lib/gitlab/metrics/transaction_spec.rb | 16 +++-------- spec/lib/gitlab/metrics_spec.rb | 6 +++++ 10 files changed, 50 insertions(+), 54 deletions(-) diff --git a/CHANGELOG b/CHANGELOG index f4567fc5bbd..11df072eaf7 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -15,6 +15,7 @@ v 8.11.0 (unreleased) - Add build event color in HipChat messages (David Eisner) - Make fork counter always clickable. !5463 (winniehell) - All created issues, API or WebUI, can be submitted to Akismet for spam check !5333 + - The overhead of instrumented method calls has been reduced - Remove `search_id` of labels dropdown filter to fix 'Missleading URI for labels in Merge Requests and Issues view'. !5368 (Scott Le) - Load project invited groups and members eagerly in `ProjectTeam#fetch_members` - Make branches sortable without push permission !5462 (winniehell) diff --git a/lib/gitlab/metrics.rb b/lib/gitlab/metrics.rb index 49f702f91f6..86a5b9a201a 100644 --- a/lib/gitlab/metrics.rb +++ b/lib/gitlab/metrics.rb @@ -124,6 +124,11 @@ module Gitlab trans.action = action if trans end + # Returns the prefix to use for the name of a series. + def self.series_prefix + @series_prefix ||= Sidekiq.server? ? 'sidekiq_' : 'rails_' + end + # When enabled this should be set before being used as the usual pattern # "@foo ||= bar" is _not_ thread-safe. if enabled? diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb index dcec7543c13..4b7a791e497 100644 --- a/lib/gitlab/metrics/instrumentation.rb +++ b/lib/gitlab/metrics/instrumentation.rb @@ -9,14 +9,17 @@ module Gitlab # # Gitlab::Metrics::Instrumentation.instrument_method(User, :by_login) module Instrumentation - SERIES = 'method_calls' - PROXY_IVAR = :@__gitlab_instrumentation_proxy def self.configure yield self end + # Returns the name of the series to use for storing method calls. + def self.series + @series ||= "#{Metrics.series_prefix}method_calls" + end + # Instruments a class method. # # mod - The module to instrument as a Module/Class. @@ -141,15 +144,15 @@ module Gitlab # generated method _only_ accepts regular arguments if the underlying # method also accepts them. if method.arity == 0 - args_signature = '&block' + args_signature = '' else - args_signature = '*args, &block' + args_signature = '*args' end proxy_module.class_eval <<-EOF, __FILE__, __LINE__ + 1 def #{name}(#{args_signature}) if trans = Gitlab::Metrics::Instrumentation.transaction - trans.measure_method(#{label.inspect}) { super } + trans.method_call_for(#{label.to_sym.inspect}).measure { super } else super end diff --git a/lib/gitlab/metrics/method_call.rb b/lib/gitlab/metrics/method_call.rb index c048fe20ba7..d3465e5ec19 100644 --- a/lib/gitlab/metrics/method_call.rb +++ b/lib/gitlab/metrics/method_call.rb @@ -11,8 +11,8 @@ module Gitlab def initialize(name, series) @name = name @series = series - @real_time = 0.0 - @cpu_time = 0.0 + @real_time = 0 + @cpu_time = 0 @call_count = 0 end diff --git a/lib/gitlab/metrics/system.rb b/lib/gitlab/metrics/system.rb index 82c18bb108b..287b7a83547 100644 --- a/lib/gitlab/metrics/system.rb +++ b/lib/gitlab/metrics/system.rb @@ -35,12 +35,12 @@ module Gitlab if Process.const_defined?(:CLOCK_THREAD_CPUTIME_ID) def self.cpu_time Process. - clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond).to_f + clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond) end else def self.cpu_time Process. - clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond).to_f + clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond) end end @@ -48,14 +48,14 @@ module Gitlab # # Returns the time as a Float. def self.real_time(precision = :millisecond) - Process.clock_gettime(Process::CLOCK_REALTIME, precision).to_f + Process.clock_gettime(Process::CLOCK_REALTIME, precision) 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 + Process.clock_gettime(Process::CLOCK_MONOTONIC, precision) end end end diff --git a/lib/gitlab/metrics/transaction.rb b/lib/gitlab/metrics/transaction.rb index bded245da43..968f3218950 100644 --- a/lib/gitlab/metrics/transaction.rb +++ b/lib/gitlab/metrics/transaction.rb @@ -52,23 +52,16 @@ module Gitlab end def add_metric(series, values, tags = {}) - @metrics << Metric.new("#{series_prefix}#{series}", values, tags) + @metrics << Metric.new("#{Metrics.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) + # Returns a MethodCall object for the given name. + def method_call_for(name) + unless method = @methods[name] + @methods[name] = method = MethodCall.new(name, Instrumentation.series) end - @methods[name].measure(&block) + method end def increment(name, value) @@ -115,14 +108,6 @@ module Gitlab 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 8809b7e3f12..d88bcae41fb 100644 --- a/spec/lib/gitlab/metrics/instrumentation_spec.rb +++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb @@ -39,6 +39,12 @@ describe Gitlab::Metrics::Instrumentation do allow(@dummy).to receive(:name).and_return('Dummy') end + describe '.series' do + it 'returns a String' do + expect(described_class.series).to be_an_instance_of(String) + end + end + describe '.configure' do it 'yields self' do described_class.configure do |c| @@ -78,8 +84,7 @@ describe Gitlab::Metrics::Instrumentation do allow(described_class).to receive(:transaction). and_return(transaction) - expect(transaction).to receive(:measure_method). - with('Dummy.foo') + expect_any_instance_of(Gitlab::Metrics::MethodCall).to receive(:measure) @dummy.foo end @@ -157,8 +162,7 @@ describe Gitlab::Metrics::Instrumentation do allow(described_class).to receive(:transaction). and_return(transaction) - expect(transaction).to receive(:measure_method). - with('Dummy#bar') + expect_any_instance_of(Gitlab::Metrics::MethodCall).to receive(:measure) @dummy.new.bar end diff --git a/spec/lib/gitlab/metrics/system_spec.rb b/spec/lib/gitlab/metrics/system_spec.rb index cf0e282c2fb..9e2ea89a712 100644 --- a/spec/lib/gitlab/metrics/system_spec.rb +++ b/spec/lib/gitlab/metrics/system_spec.rb @@ -28,20 +28,20 @@ describe Gitlab::Metrics::System do end describe '.cpu_time' do - it 'returns a Float' do - expect(described_class.cpu_time).to be_an_instance_of(Float) + it 'returns a Fixnum' do + expect(described_class.cpu_time).to be_an_instance_of(Fixnum) end end describe '.real_time' do - it 'returns a Float' do - expect(described_class.real_time).to be_an_instance_of(Float) + it 'returns a Fixnum' do + expect(described_class.real_time).to be_an_instance_of(Fixnum) end end describe '.monotonic_time' do - it 'returns a Float' do - expect(described_class.monotonic_time).to be_an_instance_of(Float) + it 'returns a Fixnum' do + expect(described_class.monotonic_time).to be_an_instance_of(Fixnum) end end end diff --git a/spec/lib/gitlab/metrics/transaction_spec.rb b/spec/lib/gitlab/metrics/transaction_spec.rb index 3b1c67a2147..f1a191d9410 100644 --- a/spec/lib/gitlab/metrics/transaction_spec.rb +++ b/spec/lib/gitlab/metrics/transaction_spec.rb @@ -46,19 +46,11 @@ 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' } + describe '#method_call_for' do + it 'returns a MethodCall' do + method = transaction.method_call_for('Foo#bar') - 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) + expect(method).to be_an_instance_of(Gitlab::Metrics::MethodCall) end end diff --git a/spec/lib/gitlab/metrics_spec.rb b/spec/lib/gitlab/metrics_spec.rb index 96f7eabbca6..84f9475a0f8 100644 --- a/spec/lib/gitlab/metrics_spec.rb +++ b/spec/lib/gitlab/metrics_spec.rb @@ -147,4 +147,10 @@ describe Gitlab::Metrics do end end end + + describe '#series_prefix' do + it 'returns a String' do + expect(described_class.series_prefix).to be_an_instance_of(String) + end + end end