From 1b077d2d81bd25fe37492ea56c8bd884f944ce52 Mon Sep 17 00:00:00 2001
From: Yorick Peterse <yorickpeterse@gmail.com>
Date: Thu, 10 Dec 2015 15:16:56 +0100
Subject: [PATCH] Use custom code for instrumenting method calls
The use of ActiveSupport would slow down instrumented method calls by
about 180x due to:
1. ActiveSupport itself not being the fastest thing on the planet
2. caller_locations() having quite some overhead
The use of caller_locations() has been removed because it's not _that_
useful since we already know the full namespace of receivers and the
names of the called methods.
The use of ActiveSupport has been replaced with some custom code that's
generated using eval() (which can be quite a bit faster than using
define_method).
This new setup results in instrumented methods only being about 35-40x
slower (compared to non instrumented methods).
---
config/initializers/metrics.rb | 1 -
lib/gitlab/metrics/instrumentation.rb | 37 +++++++++++++---
lib/gitlab/metrics/subscribers/method_call.rb | 42 -------------------
.../gitlab/metrics/instrumentation_spec.rb | 22 +++++++---
.../metrics/subscribers/method_call_spec.rb | 40 ------------------
5 files changed, 47 insertions(+), 95 deletions(-)
delete mode 100644 lib/gitlab/metrics/subscribers/method_call.rb
delete mode 100644 spec/lib/gitlab/metrics/subscribers/method_call_spec.rb
diff --git a/config/initializers/metrics.rb b/config/initializers/metrics.rb
index bde04232725..556e968137e 100644
--- a/config/initializers/metrics.rb
+++ b/config/initializers/metrics.rb
@@ -7,7 +7,6 @@ if Gitlab::Metrics.enabled?
# ActiveSupport.
require 'gitlab/metrics/subscribers/action_view'
require 'gitlab/metrics/subscribers/active_record'
- require 'gitlab/metrics/subscribers/method_call'
Gitlab::Application.configure do |config|
config.middleware.use(Gitlab::Metrics::RackMiddleware)
diff --git a/lib/gitlab/metrics/instrumentation.rb b/lib/gitlab/metrics/instrumentation.rb
index 982e35adfc9..5b56f2e8513 100644
--- a/lib/gitlab/metrics/instrumentation.rb
+++ b/lib/gitlab/metrics/instrumentation.rb
@@ -9,6 +9,8 @@ module Gitlab
#
# Gitlab::Metrics::Instrumentation.instrument_method(User, :by_login)
module Instrumentation
+ SERIES = 'method_calls'
+
# Instruments a class method.
#
# mod - The module to instrument as a Module/Class.
@@ -31,19 +33,42 @@ module Gitlab
alias_name = "_original_#{name}"
target = type == :instance ? mod : mod.singleton_class
+ if type == :instance
+ target = mod
+ label = "#{mod.name}##{name}"
+ else
+ target = mod.singleton_class
+ label = "#{mod.name}.#{name}"
+ end
+
target.class_eval <<-EOF, __FILE__, __LINE__ + 1
alias_method :#{alias_name}, :#{name}
def #{name}(*args, &block)
- ActiveSupport::Notifications
- .instrument("#{type}_method.method_call",
- module: #{mod.name.inspect},
- name: #{name.inspect}) do
- #{alias_name}(*args, &block)
- end
+ trans = Gitlab::Metrics::Instrumentation.transaction
+
+ if trans
+ start = Time.now
+ retval = #{alias_name}(*args, &block)
+ duration = (Time.now - start) * 1000.0
+
+ trans.add_metric(Gitlab::Metrics::Instrumentation::SERIES,
+ { duration: duration },
+ method: #{label.inspect})
+
+ retval
+ else
+ #{alias_name}(*args, &block)
+ end
end
EOF
end
+
+ # Small layer of indirection to make it easier to stub out the current
+ # transaction.
+ def self.transaction
+ Transaction.current
+ end
end
end
end
diff --git a/lib/gitlab/metrics/subscribers/method_call.rb b/lib/gitlab/metrics/subscribers/method_call.rb
deleted file mode 100644
index 0094ed0dc6a..00000000000
--- a/lib/gitlab/metrics/subscribers/method_call.rb
+++ /dev/null
@@ -1,42 +0,0 @@
-module Gitlab
- module Metrics
- module Subscribers
- # Class for tracking method call timings.
- class MethodCall < ActiveSupport::Subscriber
- attach_to :method_call
-
- SERIES = 'method_calls'
-
- def instance_method(event)
- return unless current_transaction
-
- label = "#{event.payload[:module]}##{event.payload[:name]}"
-
- add_metric(label, event.duration)
- end
-
- def class_method(event)
- return unless current_transaction
-
- label = "#{event.payload[:module]}.#{event.payload[:name]}"
-
- add_metric(label, event.duration)
- end
-
- private
-
- def add_metric(label, duration)
- file, line = Metrics.last_relative_application_frame
-
- values = { duration: duration, file: file, line: line }
-
- current_transaction.add_metric(SERIES, values, method: label)
- end
-
- def current_transaction
- Transaction.current
- end
- end
- end
- end
-end
diff --git a/spec/lib/gitlab/metrics/instrumentation_spec.rb b/spec/lib/gitlab/metrics/instrumentation_spec.rb
index 3e7e9869e30..9308fb157d8 100644
--- a/spec/lib/gitlab/metrics/instrumentation_spec.rb
+++ b/spec/lib/gitlab/metrics/instrumentation_spec.rb
@@ -1,6 +1,8 @@
require 'spec_helper'
describe Gitlab::Metrics::Instrumentation do
+ let(:transaction) { Gitlab::Metrics::Transaction.new }
+
before do
@dummy = Class.new do
def self.foo(text = 'foo')
@@ -31,9 +33,13 @@ describe Gitlab::Metrics::Instrumentation do
expect(@dummy.foo).to eq('foo')
end
- it 'fires an ActiveSupport notification upon calling the method' do
- expect(ActiveSupport::Notifications).to receive(:instrument).
- with('class_method.method_call', module: 'Dummy', name: :foo)
+ it 'tracks the call duration upon calling the method' do
+ allow(Gitlab::Metrics::Instrumentation).to receive(:transaction).
+ and_return(transaction)
+
+ expect(transaction).to receive(:add_metric).
+ with(described_class::SERIES, an_instance_of(Hash),
+ method: 'Dummy.foo')
@dummy.foo
end
@@ -69,9 +75,13 @@ describe Gitlab::Metrics::Instrumentation do
expect(@dummy.new.bar).to eq('bar')
end
- it 'fires an ActiveSupport notification upon calling the method' do
- expect(ActiveSupport::Notifications).to receive(:instrument).
- with('instance_method.method_call', module: 'Dummy', name: :bar)
+ it 'tracks the call duration upon calling the method' do
+ allow(Gitlab::Metrics::Instrumentation).to receive(:transaction).
+ and_return(transaction)
+
+ expect(transaction).to receive(:add_metric).
+ with(described_class::SERIES, an_instance_of(Hash),
+ method: 'Dummy#bar')
@dummy.new.bar
end
diff --git a/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb b/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb
deleted file mode 100644
index 5c76eb3ba50..00000000000
--- a/spec/lib/gitlab/metrics/subscribers/method_call_spec.rb
+++ /dev/null
@@ -1,40 +0,0 @@
-require 'spec_helper'
-
-describe Gitlab::Metrics::Subscribers::MethodCall do
- let(:transaction) { Gitlab::Metrics::Transaction.new }
-
- let(:subscriber) { described_class.new }
-
- let(:event) do
- double(:event, duration: 0.2, payload: { module: 'Foo', name: :foo })
- end
-
- before do
- allow(subscriber).to receive(:current_transaction).and_return(transaction)
-
- allow(Gitlab::Metrics).to receive(:last_relative_application_frame).
- and_return(['app/models/foo.rb', 4])
- end
-
- describe '#instance_method' do
- it 'tracks the execution of an instance method' do
- values = { duration: 0.2, file: 'app/models/foo.rb', line: 4 }
-
- expect(transaction).to receive(:add_metric).
- with(described_class::SERIES, values, method: 'Foo#foo')
-
- subscriber.instance_method(event)
- end
- end
-
- describe '#class_method' do
- it 'tracks the execution of a class method' do
- values = { duration: 0.2, file: 'app/models/foo.rb', line: 4 }
-
- expect(transaction).to receive(:add_metric).
- with(described_class::SERIES, values, method: 'Foo.foo')
-
- subscriber.class_method(event)
- end
- end
-end
--
GitLab